Add timing of individual tests, test descriptions.

1 files changed, 61 insertions, 13 deletions

diff --git a/unit_tests.py b/unit_tests.py
index a3ad19b..6634b7b 100644
--- a/unit_tests.py
+++ b/unit_tests.py
@@ -5,11 +5,17 @@ PKCS #11 unit tests, using Py11 and the Python unit_test framework.
 """
 
 import unittest
+import datetime
+import sys
 
 from py11 import *
 from py11.mutex import MutexDB
 
 
+def log(msg):
+    if not args.quiet:
+        sys.stderr.write(msg)
+
 def main():
     from sys import argv
     global args
@@ -66,13 +72,11 @@ def setUpModule():
         cmd = [args.server]
         if geteuid() != 0:
             cmd.insert(0, "sudo")
-        if not args.quiet:
-            print "Starting RPC server:", " ".join(cmd)
+        log("Starting RPC server: {}\n".format(" ".join(cmd)))
         rpc = Popen(cmd, env = dict(environ, CRYPTECH_KEYSTORE = server_keystore))
 
     # Order of PINs here is significant, see p11util for details.
-    if not args.quiet:
-        print "Setting PINs"
+    log("Setting PINs (SLOW!)\n")
     if args.wheel_pin is None:
         flags = "-sup"
         pins  = (args.initial_pin, args.so_pin, args.user_pin)
@@ -81,12 +85,10 @@ def setUpModule():
         pins  = (args.initial_pin, args.wheel_pin, args.so_pin, args.user_pin)
     Popen((args.p11util, flags), stdin = PIPE).communicate("".join(pin + "\n" for pin in pins))
 
-    if not args.quiet:
-        print "Loading PKCS #11 library", args.libpkcs11
+    log("Loading PKCS #11 library {}\n".format(args.libpkcs11))
     p11 = PKCS11(args.libpkcs11)
 
-    if not args.quiet:
-        print "Setup complete"
+    log("Setup complete\n")
 
 
 def tearDownModule():
@@ -112,30 +114,49 @@ def tearDownModule():
             check_call(("sudo", "kill", str(rpc.pid)))
 
 
-class TestInit(unittest.TestCase):
+class TimedTestCase(unittest.TestCase):
+    """
+    TestCase subclass with setUp and tearDown hooks to report
+    individual test duration.
+    """
+
+    def setUp(self):
+        self.startTime = datetime.datetime.now()
+
+    def tearDown(self):
+        self.endTime = datetime.datetime.now()
+        log("runtime {} seconds ... ".format(self.endTime - self.startTime))
+
+
+class TestInit(TimedTestCase):
     """
     Test all the flavors of C_Initialize().
     """
 
     def test_mutex_none(self):
+        "Test whether C_Initialize() works in the default case"
         p11.C_Initialize()
 
     def test_mutex_os(self):
+        "Test whether C_Initialize() works with (just) system mutexes"
         p11.C_Initialize(CKF_OS_LOCKING_OK)
 
     def test_mutex_user(self):
+        "Test whether C_Initialize() works with (just) user mutexes"
         mdb = MutexDB()
         p11.C_Initialize(0, mdb.create, mdb.destroy, mdb.lock, mdb.unlock)
 
     def test_mutex_both(self):
+        "Test whether C_Initialize() works with both system and user mutexes"
         mdb = MutexDB()
         p11.C_Initialize(CKF_OS_LOCKING_OK, mdb.create, mdb.destroy, mdb.lock, mdb.unlock)
 
     def tearDown(self):
+        super(TestKeys, self).setUp()
         p11.C_Finalize()
 
 
-class TestDevice(unittest.TestCase):
+class TestDevice(TimedTestCase):
     """
     Test basic device stuff like C_GetSlotList(), C_OpenSession(), and C_Login().
     """
@@ -149,22 +170,27 @@ class TestDevice(unittest.TestCase):
         p11.C_Finalize()
 
     def tearDown(self):
+        super(TestKeys, self).setUp()
         p11.C_CloseAllSessions(args.slot)
 
     def test_getSlots(self):
+        "Test C_GetSlots()"
         self.assertEqual(p11.C_GetSlotList(), (args.slot,))
 
     def test_getTokenInfo(self):
+        "Test C_GetTokenInfo()"
         token_info = p11.C_GetTokenInfo(args.slot)
         self.assertIsInstance(token_info, CK_TOKEN_INFO)
         self.assertEqual(token_info.label.rstrip(), "Cryptech Token")
 
     def test_sessions_serial(self):
+        "Test C_OpenSession() for useful (serial) cases"
         rw_session = p11.C_OpenSession(args.slot, CKF_RW_SESSION | CKF_SERIAL_SESSION)
         ro_session = p11.C_OpenSession(args.slot, CKF_SERIAL_SESSION)
 
     def test_sessions_parallel(self):
-        # Cooked API doesn't allow this mistake, must use raw API to test
+        "Test that C_OpenSession() rejects forbidden (parallel) cases"
+        # Cooked API doesn't allow user to make this mistake, must use raw API to test
         from ctypes import byref
         handle = CK_SESSION_HANDLE()
         notify = CK_NOTIFY()
@@ -174,12 +200,14 @@ class TestDevice(unittest.TestCase):
             p11.so.C_OpenSession(args.slot, 0,              None, notify, byref(handle))
 
     def test_login_user(self):
+        "Test C_Login() with user PIN"
         rw_session = p11.C_OpenSession(args.slot, CKF_RW_SESSION | CKF_SERIAL_SESSION)
         ro_session = p11.C_OpenSession(args.slot, CKF_SERIAL_SESSION)
         p11.C_Login(ro_session, CKU_USER, args.user_pin)
         p11.C_Logout(ro_session)
 
     def test_login_so(self):
+        "Test C_login with SO PIN"
         rw_session = p11.C_OpenSession(args.slot, CKF_RW_SESSION | CKF_SERIAL_SESSION)
         ro_session = p11.C_OpenSession(args.slot, CKF_SERIAL_SESSION)
         self.assertRaises(CKR_SESSION_READ_ONLY_EXISTS, p11.C_Login, ro_session, CKU_SO, args.so_pin)
@@ -189,8 +217,9 @@ class TestDevice(unittest.TestCase):
         p11.C_Logout(rw_session)
 
     def test_random(self):
+        "Test that C_GenerateRandom() returns, um, something"
         # Testing that what this produces really is random seems beyond
-        # the scope of a unit test.
+        # the scope of a unit test, but feel free to send code.
         session = p11.C_OpenSession(args.slot)
         n = 17
         random = p11.C_GenerateRandom(session, n)
@@ -198,6 +227,7 @@ class TestDevice(unittest.TestCase):
         self.assertEqual(len(random), n)
 
     def test_findObjects(self):
+        "Test basic C_FindObjects*() behavior"
         session = p11.C_OpenSession(args.slot)
         p11.C_FindObjectsInit(session, CKA_CLASS = CKO_PUBLIC_KEY)
         with self.assertRaises(CKR_OPERATION_ACTIVE):
@@ -207,7 +237,7 @@ class TestDevice(unittest.TestCase):
         p11.C_FindObjectsFinal(session)
 
 
-class TestKeys(unittest.TestCase):
+class TestKeys(TimedTestCase):
     """
     Tests involving keys.
     """
@@ -227,8 +257,10 @@ class TestKeys(unittest.TestCase):
     def setUp(self):
         self.session = p11.C_OpenSession(args.slot)
         p11.C_Login(self.session, CKU_USER, args.user_pin)
+        super(TestKeys, self).setUp()
 
     def tearDown(self):
+        super(TestKeys, self).setUp()
         for handle in p11.FindObjects(self.session):
             p11.C_DestroyObject(self.session, handle)
         p11.C_CloseAllSessions(args.slot)
@@ -240,6 +272,7 @@ class TestKeys(unittest.TestCase):
         self.assertEqual(p11.C_GetAttributeValue(self.session, private_handle, CKA_CLASS), {CKA_CLASS: CKO_PRIVATE_KEY})
 
     def test_keygen_token_vs_session(self):
+        "Test C_GenerateKeypair() CKA_TOKEN restrictions"
 
         with self.assertRaises(CKR_TEMPLATE_INCONSISTENT):
             p11.C_GenerateKeyPair(self.session, CKM_EC_KEY_PAIR_GEN, CKA_TOKEN = False,
@@ -264,6 +297,7 @@ class TestKeys(unittest.TestCase):
                                   CKA_SIGN = True, CKA_VERIFY = True)
 
     def test_gen_sign_verify_ecdsa_p256_sha256(self):
+        "Generate/sign/verify with ECDSA-P256-SHA-256"
         public_key, private_key = p11.C_GenerateKeyPair(self.session, CKM_EC_KEY_PAIR_GEN,
                                                         CKA_ID = "EC-P256", CKA_EC_PARAMS = self.oid_p256,
                                                         CKA_SIGN = True, CKA_VERIFY = True, CKA_TOKEN = True)
@@ -276,6 +310,7 @@ class TestKeys(unittest.TestCase):
         p11.C_Verify(self.session, hamster, sig)
 
     def test_gen_sign_verify_ecdsa_p384_sha384(self):
+        "Generate/sign/verify with ECDSA-P384-SHA-384"
         #if not args.all_tests: self.skipTest("SHA-384 not available in current build")
         public_key, private_key = p11.C_GenerateKeyPair(self.session, CKM_EC_KEY_PAIR_GEN,
                                                         CKA_ID = "EC-P384", CKA_EC_PARAMS = self.oid_p384,
@@ -289,6 +324,7 @@ class TestKeys(unittest.TestCase):
         p11.C_Verify(self.session, hamster, sig)
 
     def test_gen_sign_verify_ecdsa_p521_sha512(self):
+        "Generate/sign/verify with ECDSA-P521-SHA-512"
         #if not args.all_tests: self.skipTest("SHA-512 not available in current build")
         public_key, private_key = p11.C_GenerateKeyPair(self.session, CKM_EC_KEY_PAIR_GEN,
                                                         CKA_ID = "EC-P521", CKA_EC_PARAMS = self.oid_p521,
@@ -302,6 +338,8 @@ class TestKeys(unittest.TestCase):
         p11.C_Verify(self.session, hamster, sig)
 
     def test_gen_sign_verify_rsa_1024(self):
+        "Generate/sign/verify with RSA-1024-SHA-512"
+        "RSA 1024-bit generate/sign/verify test"
         public_key, private_key = p11.C_GenerateKeyPair(
             self.session, CKM_RSA_PKCS_KEY_PAIR_GEN, CKA_MODULUS_BITS = 1024,
             CKA_ID = "RSA-1024", CKA_SIGN = True, CKA_VERIFY = True, CKA_TOKEN = True)
@@ -314,6 +352,7 @@ class TestKeys(unittest.TestCase):
         p11.C_Verify(self.session, hamster, sig)
 
     def test_gen_sign_verify_rsa_2048(self):
+        "Generate/sign/verify with RSA-2048-SHA-512"
         #if not args.all_tests: self.skipTest("RSA key generation is still painfully slow")
         public_key, private_key = p11.C_GenerateKeyPair(
             self.session, CKM_RSA_PKCS_KEY_PAIR_GEN, CKA_MODULUS_BITS = 2048,
@@ -339,6 +378,7 @@ class TestKeys(unittest.TestCase):
         return tag + length + value
 
     def test_canned_ecdsa_p256_verify(self):
+        "EC-P-256 verification test from Suite B Implementer's Guide to FIPS 186-3"
         Q = self._build_ecpoint(0x8101ece47464a6ead70cf69a6e2bd3d88691a3262d22cba4f7635eaff26680a8,
                                 0xd8a12ba61d599235f67d9cb4d58f1783d3ca43e78f0a5abaa624079936c0c3a9)
         H = "7c3e883ddc8bd688f96eac5e9324222c8f30f9d6bb59e9c5f020bd39ba2b8377".decode("hex")
@@ -357,6 +397,7 @@ class TestKeys(unittest.TestCase):
         p11.C_Verify(self.session, H, r + s)
 
     def test_canned_ecdsa_p384_verify(self):
+        "EC-P-384 verification test from Suite B Implementer's Guide to FIPS 186-3"
         Q = self._build_ecpoint(0x1fbac8eebd0cbf35640b39efe0808dd774debff20a2a329e91713baf7d7f3c3e81546d883730bee7e48678f857b02ca0,
                                 0xeb213103bd68ce343365a8a4c3d4555fa385f5330203bdd76ffad1f3affb95751c132007e1b240353cb0a4cf1693bdf9)
         H = "b9210c9d7e20897ab86597266a9d5077e8db1b06f7220ed6ee75bd8b45db37891f8ba5550304004159f4453dc5b3f5a1".decode("hex")
@@ -375,6 +416,7 @@ class TestKeys(unittest.TestCase):
         p11.C_Verify(self.session, H, r + s)
 
     def test_gen_sign_verify_reload_ecdsa_p256_sha256(self):
+        "Generate/sign/verify/destroy/reload/verify with ECDSA-P256-SHA-256"
         public_key, private_key = p11.C_GenerateKeyPair(self.session, CKM_EC_KEY_PAIR_GEN,
                                                         public_CKA_TOKEN = False, private_CKA_TOKEN = True,
                                                         CKA_ID = "EC-P256", CKA_EC_PARAMS = self.oid_p256,
@@ -414,6 +456,7 @@ class TestKeys(unittest.TestCase):
         self.assertEqual(result, expect)
 
     def test_gen_sign_verify_tralala_rsa_1024(self):
+        "Generate/sign/verify with RSA-1024 (no hashing, message to be signed not a hash at all)"
         tralala = "tralala-en-hopsasa"
         public_key, private_key = p11.C_GenerateKeyPair(
             self.session, CKM_RSA_PKCS_KEY_PAIR_GEN, CKA_MODULUS_BITS = 1024,
@@ -427,6 +470,7 @@ class TestKeys(unittest.TestCase):
         p11.C_Verify(self.session, tralala, sig)
 
     def test_gen_sign_verify_tralala_rsa_3416(self):
+        "Generate/sign/verify with RSA-3416 (no hashing, message to be signed not a hash at all)"
         tralala = "tralala-en-hopsasa"
         public_key, private_key = p11.C_GenerateKeyPair(
             self.session, CKM_RSA_PKCS_KEY_PAIR_GEN, CKA_MODULUS_BITS = 3416,
@@ -440,6 +484,7 @@ class TestKeys(unittest.TestCase):
         p11.C_Verify(self.session, tralala, sig)
 
     def test_load_sign_verify_rsa_3416(self):
+        "Load/sign/verify with RSA-3416 and externally-supplied key (no hashing, message to be signed not a hash at all)"
         from Crypto.Util.number import long_to_bytes, inverse
         from Crypto.PublicKey   import RSA
         from textwrap           import dedent
@@ -514,6 +559,7 @@ class TestKeys(unittest.TestCase):
         p11.C_Verify(self.session, hamster, sig)
 
     def test_gen_sign_verify_rsa_3416(self):
+        "Generate/sign/verify with RSA-3416-SHA-512"
         public_key, private_key = p11.C_GenerateKeyPair(
             self.session, CKM_RSA_PKCS_KEY_PAIR_GEN, CKA_MODULUS_BITS = 3416,
             CKA_ID = "RSA-3416", CKA_SIGN = True, CKA_VERIFY = True, CKA_TOKEN = True)
@@ -526,12 +572,14 @@ class TestKeys(unittest.TestCase):
         p11.C_Verify(self.session, hamster, sig)
 
     def test_gen_rsa_1028(self):
+        "Test that C_GenerateKeyPair() rejects key length not multiple of 8 bits"
         with self.assertRaises(CKR_ATTRIBUTE_VALUE_INVALID):
             p11.C_GenerateKeyPair(
                 self.session, CKM_RSA_PKCS_KEY_PAIR_GEN, CKA_MODULUS_BITS = 1028,
                 CKA_ID = "RSA-1028", CKA_SIGN = True, CKA_VERIFY = True, CKA_TOKEN = True)
 
     def test_gen_sign_verify_rsa_1032(self):
+        "Generate/sign/verify with RSA-1032-SHA-512 (sic)"
         public_key, private_key = p11.C_GenerateKeyPair(
             self.session, CKM_RSA_PKCS_KEY_PAIR_GEN, CKA_MODULUS_BITS = 1032,
             CKA_ID = "RSA-1032", CKA_SIGN = True, CKA_VERIFY = True, CKA_TOKEN = True)