Log pefromance related data

src/dl.c

@@ -26,36 +26,152 @@
  // Platform dependend function that loads dynamic library
 DLHANDLE pkcs11_logger_dl_open(const char* library)
 {
+    DLHANDLE handle = NULL;
+
+    pkcs11_logger_log_with_timestamp("Loading library \"%s\"", library);
+
 #ifdef _WIN32
+
     DWORD flags = 0;
-
+    DWORD error = 0;
+
     if (CK_TRUE == pkcs11_logger_utils_path_is_absolute(library))
         flags = LOAD_WITH_ALTERED_SEARCH_PATH;
 
-    return LoadLibraryExA(library, NULL, flags);
+    handle = LoadLibraryExA(library, NULL, flags);
+    if (NULL == handle)
+    {
+        error = GetLastError();
+        pkcs11_logger_log_with_timestamp("Unable to load library. Error: %0#10x", error);
+    }
+    else
+    {
+        pkcs11_logger_log_with_timestamp("Successfully loaded library");
+    }
+
 #else
-    return dlopen(library, RTLD_NOW | RTLD_LOCAL);
+
+    char* error = NULL;
+
+    handle = dlopen(library, RTLD_NOW | RTLD_LOCAL);
+    if (NULL == handle)
+    {
+        error = dlerror();
+        if (NULL != error)
+        {
+            pkcs11_logger_log_with_timestamp("Unable to load library. Error: %s", error);
+        }
+        else
+        {
+            pkcs11_logger_log_with_timestamp("Unable to load library");
+        }
+    }
+    else
+    {
+        pkcs11_logger_log_with_timestamp("Successfully loaded library");
+    }
+
 #endif
+
+    return handle;
 }
 
 
 // Platform dependend function that gets function pointer from dynamic library
 void *pkcs11_logger_dl_sym(DLHANDLE library, const char *function)
 {
+    void *address = NULL;
+
+    pkcs11_logger_log_with_timestamp("Retrieving function pointer for %s", function);
+
 #ifdef _WIN32
-    return (void*) GetProcAddress(library, function);
+
+    DWORD error = 0;
+
+    address = (void*) GetProcAddress(library, function);
+    if (NULL == address)
+    {
+        error = GetLastError();
+        pkcs11_logger_log_with_timestamp("Unable to retrieve function pointer. Error: %0#10x", error);
+    }
+    else
+    {
+        pkcs11_logger_log_with_timestamp("Successfully retrieved function pointer");
+    }
+
 #else
-    return dlsym(library, function);
+
+    char* error = NULL;
+
+    address = dlsym(library, function);
+    if (NULL == address)
+    {
+        error = dlerror();
+        if (NULL != error)
+        {
+            pkcs11_logger_log_with_timestamp("Unable to retrieve function pointer. Error: %s", error);
+        }
+        else
+        {
+            pkcs11_logger_log_with_timestamp("Unable to retrieve function pointer");
+        }
+    }
+    else
+    {
+        pkcs11_logger_log_with_timestamp("Successfully retrieved function pointer");
+    }
+
 #endif
+
+    return address;
 }
 
 
 // Platform dependend function that unloads dynamic library
 int pkcs11_logger_dl_close(DLHANDLE library)
 {
+    int rv = 0;
+
+    pkcs11_logger_log_with_timestamp("Unloading library");
+
 #ifdef _WIN32
-    return FreeLibrary(library);
+
+    DWORD error = 0;
+
+    rv = FreeLibrary(library);
+    if (0 == rv)
+    {
+        error = GetLastError();
+        pkcs11_logger_log_with_timestamp("Unable to unload library. Error: %0#10x", error);
+    }
+    else
+    {
+        pkcs11_logger_log_with_timestamp("Successfully unloaded library");
+    }
+
 #else
-    return dlclose(library);
+
+    char* error = NULL;
+
+    rv = dlclose(library);
+    if (0 == rv)
+    {
+        error = dlerror();
+        if (NULL != error)
+        {
+            pkcs11_logger_log_with_timestamp("Unable to unload library. Error: %s", error);
+        }
+        else
+        {
+            pkcs11_logger_log_with_timestamp("Unable to unload library");
+        }
+    }
+    else
+    {
+        pkcs11_logger_log_with_timestamp("Successfully unloaded library");
+    }
+
 #endif
+
+    return rv;
 }

src/init.c

@@ -108,24 +108,24 @@ int pkcs11_logger_init_orig_lib(void)
     pkcs11_logger_globals.orig_lib_handle = pkcs11_logger_dl_open((const char *)pkcs11_logger_globals.env_var_library_path);
     if (NULL == pkcs11_logger_globals.orig_lib_handle)
     {
-        pkcs11_logger_log("Unable to load %s", pkcs11_logger_globals.env_var_library_path);
         return PKCS11_LOGGER_RV_ERROR;
     }
 
     // Get pointer to C_GetFunctionList()
     GetFunctionListPointer = (CK_C_GetFunctionList) pkcs11_logger_dl_sym(pkcs11_logger_globals.orig_lib_handle, "C_GetFunctionList");
     if (NULL == GetFunctionListPointer)
     {
-        pkcs11_logger_log("Unable to find C_GetFunctionList() in %s", pkcs11_logger_globals.env_var_library_path);
         CALL_N_CLEAR(pkcs11_logger_dl_close, pkcs11_logger_globals.orig_lib_handle);
         return PKCS11_LOGGER_RV_ERROR;
     }
 
     // Get pointers to all PKCS#11 functions
+    pkcs11_logger_log_with_timestamp("Calling C_GetFunctionList function");
     rv = GetFunctionListPointer(&(pkcs11_logger_globals.orig_lib_functions));
+    pkcs11_logger_log_with_timestamp("Received response from C_GetFunctionList function");
     if (CKR_OK != rv)
     {
-        pkcs11_logger_log("Unable to call C_GetFunctionList() from %s", pkcs11_logger_globals.env_var_library_path);
+        pkcs11_logger_log("C_GetFunctionList returned %lu (%s)", rv, pkcs11_logger_translate_ck_rv(rv));
         CALL_N_CLEAR(pkcs11_logger_dl_close, pkcs11_logger_globals.orig_lib_handle);
         return PKCS11_LOGGER_RV_ERROR;
     }
@@ -135,8 +135,8 @@ int pkcs11_logger_init_orig_lib(void)
     pkcs11_logger_globals.logger_functions.version.minor = pkcs11_logger_globals.orig_lib_functions->version.minor;
 
     // Everything is set up
-    pkcs11_logger_log("Successfuly loaded %s", pkcs11_logger_globals.env_var_library_path);
-    pkcs11_logger_log("Memory contents are dumped without endianness conversion");
+    pkcs11_logger_log_separator();
+    pkcs11_logger_log("NOTE: Memory contents will be logged without the endianness conversion");
 
     return PKCS11_LOGGER_RV_SUCCESS;
 }

src/log.c

@@ -117,27 +117,55 @@ void pkcs11_logger_log(const char* message, ...)
 }
 
 
+// Logs message with prepended timestamp
+void pkcs11_logger_log_with_timestamp(const char* message, ...)
+{
+    char* message_string = NULL;
+    int message_string_len = 0;
+
+    va_list ap;
+    va_start(ap, message);
+    message_string_len = vsnprintf(NULL, 0, message, ap);
+    va_end(ap);
+
+    message_string = (char*) malloc(message_string_len + 1);
+    if (NULL == message_string)
+        return;
+
+    memset(message_string, 0, message_string_len + 1);
+
+    va_start(ap, message);
+    vsnprintf(message_string, message_string_len + 1, message, ap);
+    va_end(ap);
+
+    char time_string[27];
+    pkcs11_logger_utils_get_current_time_str(time_string, sizeof(time_string));
+
+    pkcs11_logger_log("%s - %s", time_string, message_string);
+
+    CALL_N_CLEAR(free, message_string);
+}
+
+
 // Logs separator line
 void pkcs11_logger_log_separator(void)
 {
-    char str_time[27];
-    pkcs11_logger_utils_get_current_time_str(str_time, sizeof(str_time));
-    pkcs11_logger_log("*************** %s ***", str_time);
+    pkcs11_logger_log("******************************************************************************************************************************");
 }
 
 
-// Logs function call
+// Logs entry into logger function
 void pkcs11_logger_log_function_enter(const char *function)
 {
     pkcs11_logger_log_separator();
-    pkcs11_logger_log("Calling %s", function);
+    pkcs11_logger_log_with_timestamp("Entered %s", function);
 }
 
 
-// Logs function exit
+// Logs exit from logger function
 void pkcs11_logger_log_function_exit(CK_RV rv)
 {
-    pkcs11_logger_log("Returning %lu (%s)", rv, pkcs11_logger_translate_ck_rv(rv));
+    pkcs11_logger_log_with_timestamp("Returning %lu (%s)", rv, pkcs11_logger_translate_ck_rv(rv));
 }
 
 
@@ -148,6 +176,20 @@ void pkcs11_logger_log_input_params(void)
 }
 
 
+// Logs entry into original function
+void pkcs11_logger_log_orig_function_enter(const char* function)
+{
+    pkcs11_logger_log_with_timestamp("Calling %s", function);
+}
+
+
+// Logs exit from original function
+void pkcs11_logger_log_orig_function_exit(const char* function)
+{
+    pkcs11_logger_log_with_timestamp("Received response from %s", function);
+}
+
+
 // Logs output params notice
 void pkcs11_logger_log_output_params(void)
 {