void pkcs11_logger_log(const char* message, ...)
{
FILE *fw = NULL;
FILE *output = stdout;
va_list ap;
// Acquire exclusive access to the file
pkcs11_logger_lock_acquire();
va_start(ap, message);
// Determine log filename
char *log_file_name = getenv("PKCS11_LOGGER_LOG_FILE");
if (NULL == log_file_name)
log_file_name = DEFAULT_PKCS11_LOGGER_LOG_FILE;
// Open log file
fw = fopen(log_file_name, "a");
if (NULL != fw)
output = fw;
// Output message to log file or stdout
fprintf(output, "%0#10x : ", get_process_id());
fprintf(output, "%0#10x : ", get_thread_id());
vfprintf(output, message, ap);
fprintf(output, "\n");
// Cleanup
va_end(ap);
CALL_N_CLEAR(fclose, fw);
// Release exclusive access to the file
pkcs11_logger_lock_release();
}
void pkcs11_logger_log_attribute_template_with_indent(CK_ATTRIBUTE_PTR pTemplate, CK_ULONG ulCount, int level)
{
int i = 0;
char indent[level*3+1];
char horizontal_line[] = "--------------------------------------";
if ((NULL == pTemplate) || (ulCount < 1))
return;
for(i = 0; i < level*3+1; i++)
{
indent[i] = ' ';
}
if(i > 1) {
indent[i++] = '|';
}
indent[i] = '\0';
for (i = 0; i < ulCount; i++)
{
pkcs11_logger_log("%s Attribute %d", indent, i);
pkcs11_logger_log("%s Attribute: %lu (%s)", indent, pTemplate[i].type, pkcs11_logger_translate_ck_attribute(pTemplate[i].type));
pkcs11_logger_log("%s pValue: %p", indent, pTemplate[i].pValue);
pkcs11_logger_log("%s ulValueLen: %lu", indent, pTemplate[i].ulValueLen);
if (NULL != pTemplate[i].pValue)
{
char *value = NULL;
if(0x40000000 & pTemplate[i].type)
{
pkcs11_logger_log("%s *pValue: is nested attribute array", indent);
pkcs11_logger_log("%s %s", indent, horizontal_line);
pkcs11_logger_log_attribute_template_with_indent(pTemplate[i].pValue, pTemplate[i].ulValueLen / sizeof(CK_ATTRIBUTE), level + 1);
pkcs11_logger_log("%s %s", indent, horizontal_line);
}
else
{
value = pkcs11_logger_translate_ck_byte_ptr(pTemplate[i].pValue, pTemplate[i].ulValueLen);
if (NULL != value)
{
pkcs11_logger_log("%s *pValue: HEX(%s)", indent, value);
CALL_N_CLEAR(free, value);
}
else
{
pkcs11_logger_log("%s *pValue: *** cannot be displayed ***", indent);
}
}
}
}
}
void pkcs11_logger_log_byte_array(const char *name, CK_BYTE_PTR byte_array, CK_ULONG byte_array_len)
{
if (NULL != byte_array)
{
char *array = NULL;
array = pkcs11_logger_translate_ck_byte_ptr(byte_array, byte_array_len);
if (NULL != array)
{
pkcs11_logger_log("%s: HEX(%s)", name, array);
CALL_N_CLEAR(free, array);
}
else
{
pkcs11_logger_log("%s: *** cannot be displayed ***", name);
}
}
}
// Logs array of cryptoki attributes
void pkcs11_logger_log_attribute_template(CK_ATTRIBUTE_PTR pTemplate, CK_ULONG ulCount)
{
CK_ULONG i = 0;
if ((NULL == pTemplate) || (ulCount < 1))
return;
pkcs11_logger_log(" *** Begin attribute template ***");
for (i = 0; i < ulCount; i++)
{
pkcs11_logger_log(" Attribute %d", i);
pkcs11_logger_log(" Attribute: %lu (%s)", pTemplate[i].type, pkcs11_logger_translate_ck_attribute(pTemplate[i].type));
pkcs11_logger_log(" pValue: %p", pTemplate[i].pValue);
pkcs11_logger_log(" ulValueLen: %lu", pTemplate[i].ulValueLen);
if (NULL != pTemplate[i].pValue)
{
char *value = NULL;
if ((pTemplate[i].type & CKF_ARRAY_ATTRIBUTE) == CKF_ARRAY_ATTRIBUTE)
{
if (0 == (pTemplate[i].ulValueLen % sizeof(CK_ATTRIBUTE)))
{
pkcs11_logger_log_attribute_template(pTemplate[i].pValue, pTemplate[i].ulValueLen / sizeof(CK_ATTRIBUTE));
continue;
}
}
value = pkcs11_logger_translate_ck_byte_ptr(pTemplate[i].pValue, pTemplate[i].ulValueLen);
if (NULL != value)
{
pkcs11_logger_log(" *pValue: HEX(%s)", value);
CALL_N_CLEAR(free, value);
}
else
{
pkcs11_logger_log(" *pValue: *** cannot be displayed ***");
}
}
}
pkcs11_logger_log(" *** End attribute template ***");
}
void pkcs11_logger_log_nonzero_string(const char *name, const unsigned char *nonzero_string, CK_ULONG nonzero_string_len)
{
if (NULL != nonzero_string)
{
unsigned char *zero_string = NULL;
zero_string = (unsigned char*) malloc(nonzero_string_len + 1);
if (NULL != zero_string)
{
memset(zero_string, 0, nonzero_string_len + 1);
memcpy(zero_string, nonzero_string, nonzero_string_len);
pkcs11_logger_log("%s: %s", name, zero_string);
CALL_N_CLEAR(free, zero_string);
}
else
{
pkcs11_logger_log("%s: *** cannot be displayed ***", name);
}
}
}
// Logs message
void pkcs11_logger_log(const char* message, ...)
{
va_list ap;
unsigned long disable_log_file = ((pkcs11_logger_globals.flags & PKCS11_LOGGER_FLAG_DISABLE_LOG_FILE) == PKCS11_LOGGER_FLAG_DISABLE_LOG_FILE);
unsigned long disable_process_id = ((pkcs11_logger_globals.flags & PKCS11_LOGGER_FLAG_DISABLE_PROCESS_ID) == PKCS11_LOGGER_FLAG_DISABLE_PROCESS_ID);
unsigned long disable_thread_id = ((pkcs11_logger_globals.flags & PKCS11_LOGGER_FLAG_DISABLE_THREAD_ID) == PKCS11_LOGGER_FLAG_DISABLE_THREAD_ID);
unsigned long enable_stdout = ((pkcs11_logger_globals.flags & PKCS11_LOGGER_FLAG_ENABLE_STDOUT) == PKCS11_LOGGER_FLAG_ENABLE_STDOUT);
unsigned long enable_stderr = ((pkcs11_logger_globals.flags & PKCS11_LOGGER_FLAG_ENABLE_STDERR) == PKCS11_LOGGER_FLAG_ENABLE_STDERR);
unsigned long enable_fclose = ((pkcs11_logger_globals.flags & PKCS11_LOGGER_FLAG_ENABLE_FCLOSE) == PKCS11_LOGGER_FLAG_ENABLE_FCLOSE);
// Acquire exclusive access to the file
pkcs11_logger_lock_acquire();
#ifdef _WIN32
#pragma warning(push)
#pragma warning(disable: 4996)
#endif
// Open log file
if ((!disable_log_file) && (NULL != pkcs11_logger_globals.env_var_log_file_path) && (NULL == pkcs11_logger_globals.log_file_handle))
{
pkcs11_logger_globals.log_file_handle = fopen((const char *)pkcs11_logger_globals.env_var_log_file_path, "a");
}
#ifdef _WIN32
#pragma warning(pop)
#endif
// Log to file
if ((!disable_log_file) && (NULL != pkcs11_logger_globals.log_file_handle))
{
va_start(ap, message);
if (!disable_process_id)
fprintf(pkcs11_logger_globals.log_file_handle, "%0#10x : ", pkcs11_logger_utils_get_process_id());
if (!disable_thread_id)
fprintf(pkcs11_logger_globals.log_file_handle, "%0#10x : ", pkcs11_logger_utils_get_thread_id());
vfprintf(pkcs11_logger_globals.log_file_handle, message, ap);
fprintf(pkcs11_logger_globals.log_file_handle, "\n");
va_end(ap);
}
// Log to stdout
if (enable_stdout)
{
va_start(ap, message);
if (!disable_process_id)
fprintf(stdout, "%0#10x : ", pkcs11_logger_utils_get_process_id());
if (!disable_thread_id)
fprintf(stdout, "%0#10x : ", pkcs11_logger_utils_get_thread_id());
vfprintf(stdout, message, ap);
fprintf(stdout, "\n");
va_end(ap);
}
// Log to stderr
if (enable_stderr || CK_FALSE == pkcs11_logger_globals.env_vars_read)
{
va_start(ap, message);
if (!disable_process_id)
fprintf(stderr, "%0#10x : ", pkcs11_logger_utils_get_process_id());
if (!disable_thread_id)
fprintf(stderr, "%0#10x : ", pkcs11_logger_utils_get_thread_id());
vfprintf(stderr, message, ap);
fprintf(stderr, "\n");
va_end(ap);
}
// Cleanup
if (enable_fclose)
{
CALL_N_CLEAR(fclose, pkcs11_logger_globals.log_file_handle);
}
else
{
if (NULL != pkcs11_logger_globals.log_file_handle)
fflush(pkcs11_logger_globals.log_file_handle);
}
// Release exclusive access to the file
pkcs11_logger_lock_release();
}