From 20bf3f5484ff2dd8a59ed5afa0c6798d7439d402 Mon Sep 17 00:00:00 2001 From: Viktor Tarasov Date: Sun, 13 May 2012 00:27:38 +0200 Subject: [PATCH] pkcs11: use short form of log messages Change-Id: Ice298552238da9eeb0b646fc1ddfaf4d7a8ee4bb --- src/pkcs11/framework-pkcs15.c | 103 +++++++++++++++++----------------- src/pkcs11/misc.c | 10 ++-- src/pkcs11/openssl.c | 6 +- src/pkcs11/pkcs11-global.c | 30 +++++----- src/pkcs11/pkcs11-object.c | 65 ++++++++++----------- src/pkcs11/pkcs11-session.c | 28 ++++----- src/pkcs11/slot.c | 40 ++++++------- 7 files changed, 140 insertions(+), 142 deletions(-) diff --git a/src/pkcs11/framework-pkcs15.c b/src/pkcs11/framework-pkcs15.c index 1537fb20..416d5276 100644 --- a/src/pkcs11/framework-pkcs15.c +++ b/src/pkcs11/framework-pkcs15.c @@ -163,19 +163,20 @@ static CK_RV pkcs15_bind(struct sc_pkcs11_card *p11card) int rc; CK_RV rv; + sc_log(context, "Bind PKCS#15 application"); if (!(fw_data = calloc(1, sizeof(*fw_data)))) return CKR_HOST_MEMORY; p11card->fw_data = fw_data; rc = sc_pkcs15_bind(p11card->card, NULL, &fw_data->p15_card); if (rc != SC_SUCCESS) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "sc_pkcs15_bind failed: %d", rc); + sc_log(context, "sc_pkcs15_bind failed: %d", rc); return sc_to_cryptoki_error(rc, NULL); } rv = register_mechanisms(p11card); if (rv != CKR_OK) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "register_mechanisms failed: 0x%x", rv); + sc_log(context, "register_mechanisms failed: 0x%x", rv); return rv; } @@ -329,7 +330,7 @@ CK_RV C_GetTokenInfo(CK_SLOT_ID slotID, CK_TOKEN_INFO_PTR pInfo) if (rv != CKR_OK) return rv; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_GetTokenInfo(%lx)", slotID); + sc_log(context, "C_GetTokenInfo(%lx)", slotID); rv = slot_get_token(slotID, &slot); if (rv != CKR_OK) @@ -490,7 +491,7 @@ __pkcs15_create_pubkey_object(struct pkcs15_fw_data *fw_data, /* if emulation already created pubkey use it */ if (pubkey->emulated && (fw_data->p15_card->flags & SC_PKCS15_CARD_FLAG_EMULATED)) { p15_key = (struct sc_pkcs15_pubkey *) pubkey->emulated; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Using emulated pubkey %p", p15_key); + sc_log(context, "Using emulated pubkey %p", p15_key); } else { if ((rv = sc_pkcs15_read_pubkey(fw_data->p15_card, pubkey, &p15_key)) < 0) @@ -572,7 +573,7 @@ pkcs15_create_pkcs11_objects(struct pkcs15_fw_data *fw_data, rv = count = sc_pkcs15_get_objects(fw_data->p15_card, p15_type, p15_object, MAX_OBJECTS); if (rv >= 0) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Found %d %s%s\n", count, + sc_log(context, "Found %d %s%s\n", count, name, (count == 1)? "" : "s"); } @@ -589,7 +590,7 @@ __pkcs15_prkey_bind_related(struct pkcs15_fw_data *fw_data, struct pkcs15_prkey_ sc_pkcs15_id_t *id = &pk->prv_info->id; unsigned int i; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Object is a private key and has id %s", + sc_log(context, "Object is a private key and has id %s", sc_pkcs15_print_id(id)); for (i = 0; i < fw_data->num_objects; i++) { @@ -615,7 +616,7 @@ __pkcs15_prkey_bind_related(struct pkcs15_fw_data *fw_data, struct pkcs15_prkey_ pubkey = (struct pkcs15_pubkey_object *) obj; if (sc_pkcs15_compare_id(&pubkey->pub_info->id, id)) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Associating object %d as public key", i); + sc_log(context, "Associating object %d as public key", i); pk->prv_pubkey = pubkey; if (pk->prv_info->modulus_length == 0) pk->prv_info->modulus_length = pubkey->pub_info->modulus_length; @@ -631,7 +632,7 @@ __pkcs15_cert_bind_related(struct pkcs15_fw_data *fw_data, struct pkcs15_cert_ob sc_pkcs15_id_t *id = &cert->cert_info->id; unsigned int i; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Object is a certificate and has id %s", + sc_log(context, "Object is a certificate and has id %s", sc_pkcs15_print_id(id)); /* Loop over all objects to see if we find the certificate of @@ -650,7 +651,7 @@ __pkcs15_cert_bind_related(struct pkcs15_fw_data *fw_data, struct pkcs15_cert_ob continue; if (c1->issuer_len == c2->subject_len && !memcmp(c1->issuer, c2->subject, c1->issuer_len)) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Associating object %d (id %s) as issuer", + sc_log(context, "Associating object %d (id %s) as issuer", i, sc_pkcs15_print_id(&cert2->cert_info->id)); cert->cert_issuer = (struct pkcs15_cert_object *) obj; return; @@ -661,7 +662,7 @@ __pkcs15_cert_bind_related(struct pkcs15_fw_data *fw_data, struct pkcs15_cert_ob pk = (struct pkcs15_prkey_object *) obj; if (sc_pkcs15_compare_id(&pk->prv_info->id, id)) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Associating object %d as private key", i); + sc_log(context, "Associating object %d as private key", i); cert->cert_prvkey = pk; } } @@ -682,7 +683,7 @@ pkcs15_bind_related_objects(struct pkcs15_fw_data *fw_data) if (obj->base.flags & SC_PKCS11_OBJECT_HIDDEN) continue; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Looking for objects related to object %d", i); + sc_log(context, "Looking for objects related to object %d", i); if (is_privkey(obj)) { __pkcs15_prkey_bind_related(fw_data, (struct pkcs15_prkey_object *) obj); @@ -750,7 +751,7 @@ pkcs15_add_object(struct sc_pkcs11_slot *slot, *pHandle = (CK_OBJECT_HANDLE)obj; /* cast pointer to long */ list_append(&slot->objects, obj); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Setting object handle of 0x%lx to 0x%lx", obj->base.handle, (CK_OBJECT_HANDLE)obj); + sc_log(context, "Setting object handle of 0x%lx to 0x%lx", obj->base.handle, (CK_OBJECT_HANDLE)obj); obj->base.handle = (CK_OBJECT_HANDLE)obj; /* cast pointer to long */ obj->base.flags |= SC_PKCS11_OBJECT_SEEN; obj->refcount++; @@ -841,7 +842,7 @@ static void pkcs15_init_slot(struct sc_pkcs15_card *p15card, if (p15card->flags & SC_PKCS15_CARD_FLAG_EMULATED) slot->token_info.flags |= CKF_WRITE_PROTECTED; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Initialized token '%s' in slot 0x%lx", tmp, slot->id); + sc_log(context, "Initialized token '%s' in slot 0x%lx", tmp, slot->id); } static CK_RV pkcs15_create_slot(struct sc_pkcs11_card *p11card, @@ -882,7 +883,7 @@ static CK_RV pkcs15_create_tokens(struct sc_pkcs11_card *p11card) SC_PKCS15_MAX_PINS); if (rv < 0) return sc_to_cryptoki_error(rv, NULL); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Found %d authentication objects\n", rv); + sc_log(context, "Found %d authentication objects\n", rv); auth_count = rv; rv = pkcs15_create_pkcs11_objects(fw_data, @@ -991,15 +992,15 @@ static CK_RV pkcs15_create_tokens(struct sc_pkcs11_card *p11card) continue; if (is_privkey(obj)) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Adding private key %d to PIN %d\n", j, i); + sc_log(context, "Adding private key %d to PIN %d\n", j, i); pkcs15_add_object(slot, obj, NULL); } else if (is_data(obj)) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Adding data object %d to PIN %d\n", j, i); + sc_log(context, "Adding data object %d to PIN %d\n", j, i); pkcs15_add_object(slot, obj, NULL); } else if (is_cert(obj)) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Adding cert object %d to PIN %d\n", j, i); + sc_log(context, "Adding cert object %d to PIN %d\n", j, i); pkcs15_add_object(slot, obj, NULL); } } @@ -1022,7 +1023,7 @@ static CK_RV pkcs15_create_tokens(struct sc_pkcs11_card *p11card) break; if (!(obj->base.flags & SC_PKCS11_OBJECT_SEEN)) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "%d: Object ('%s',type:%X) was not seen previously\n", j, + sc_log(context, "%d: Object ('%s',type:%X) was not seen previously\n", j, obj->p15_object->label, obj->p15_object->type); if (!slot) { rv = pkcs15_create_slot(p11card, NULL, &slot); @@ -1043,7 +1044,7 @@ static CK_RV pkcs15_create_tokens(struct sc_pkcs11_card *p11card) } } */ - sc_debug(context, SC_LOG_DEBUG_NORMAL, "All tokens created\n"); + sc_log(context, "All tokens created\n"); return CKR_OK; } @@ -1091,7 +1092,7 @@ static CK_RV pkcs15_login(struct sc_pkcs11_slot *slot, } } - sc_debug(context, SC_LOG_DEBUG_NORMAL, "No SOPIN found; returns %d", rc); + sc_log(context, "No SOPIN found; returns %d", rc); return sc_to_cryptoki_error(rc, "C_Login"); } else if (rc < 0) { @@ -1106,7 +1107,7 @@ static CK_RV pkcs15_login(struct sc_pkcs11_slot *slot, * using the correct auth_object. * TODO: handle the CK_SO case */ - sc_debug(context, SC_LOG_DEBUG_NORMAL, "context specific login %d", + sc_log(context, "context specific login %d", slot->login_user); if (slot->login_user == CKU_USER) { auth_object = slot_data_auth(slot->fw_data); @@ -1132,7 +1133,7 @@ static CK_RV pkcs15_login(struct sc_pkcs11_slot *slot, } } #endif - sc_debug(context, SC_LOG_DEBUG_NORMAL, "context specific login returns %d", rc); + sc_log(context, "context specific login returns %d", rc); return sc_to_cryptoki_error(rc, "C_Login"); default: return CKR_USER_TYPE_INVALID; @@ -1183,7 +1184,7 @@ static CK_RV pkcs15_login(struct sc_pkcs11_slot *slot, } rc = sc_pkcs15_verify_pin(p15card, auth_object, pPin, ulPinLen); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "PKCS15 verify PIN returned %d", rc); + sc_log(context, "PKCS15 verify PIN returned %d", rc); if (rc != SC_SUCCESS) return sc_to_cryptoki_error(rc, "C_Login"); @@ -1192,7 +1193,7 @@ static CK_RV pkcs15_login(struct sc_pkcs11_slot *slot, sc_pkcs15_object_t *p15_obj = p15card->obj_list; sc_pkcs15_search_key_t sk; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Check if pkcs15 object list can be completed."); + sc_log(context, "Check if pkcs15 object list can be completed."); /* Ensure non empty list */ if (p15_obj == NULL) @@ -1229,7 +1230,7 @@ static CK_RV pkcs15_login(struct sc_pkcs11_slot *slot, default: continue; } - sc_debug(context, SC_LOG_DEBUG_NORMAL, "new object found: type=0x%03X", p15_obj->type); + sc_log(context, "new object found: type=0x%03X", p15_obj->type); pkcs15_add_object(slot, fw_obj, NULL); } } @@ -1282,7 +1283,7 @@ static CK_RV pkcs15_change_pin(struct sc_pkcs11_card *p11card, if (!(auth_info = slot_data_auth_info(fw_token))) return CKR_USER_PIN_NOT_INITIALIZED; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Change '%s', reference %i; login type %i", + sc_log(context, "Change '%s', reference %i; login type %i", pin_obj->label, auth_info->attrs.pin.reference, login_user); if (p11card->card->reader->capabilities & SC_READER_CAP_PIN_PAD) { /* pPin should be NULL in case of a pin pad reader, but @@ -1300,14 +1301,14 @@ static CK_RV pkcs15_change_pin(struct sc_pkcs11_card *p11card, if (login_user < 0) { if (sc_pkcs11_conf.pin_unblock_style != SC_PKCS11_PIN_UNBLOCK_UNLOGGED_SETPIN) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "PIN unlock is not allowed in unlogged session"); + sc_log(context, "PIN unlock is not allowed in unlogged session"); return CKR_FUNCTION_NOT_SUPPORTED; } rc = sc_pkcs15_unblock_pin(fw_data->p15_card, pin_obj, pOldPin, ulOldLen, pNewPin, ulNewLen); } else if (login_user == CKU_CONTEXT_SPECIFIC) { if (sc_pkcs11_conf.pin_unblock_style != SC_PKCS11_PIN_UNBLOCK_SCONTEXT_SETPIN) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "PIN unlock is not allowed with CKU_CONTEXT_SPECIFIC login"); + sc_log(context, "PIN unlock is not allowed with CKU_CONTEXT_SPECIFIC login"); return CKR_FUNCTION_NOT_SUPPORTED; } rc = sc_pkcs15_unblock_pin(fw_data->p15_card, pin_obj, pOldPin, ulOldLen, pNewPin, ulNewLen); @@ -1329,18 +1330,18 @@ static CK_RV pkcs15_change_pin(struct sc_pkcs11_card *p11card, break; } if (i == auth_count) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Change SoPIN non supported"); + sc_log(context, "Change SoPIN non supported"); return CKR_FUNCTION_NOT_SUPPORTED; } rc = sc_pkcs15_change_pin(fw_data->p15_card, auths[i], pOldPin, ulOldLen, pNewPin, ulNewLen); } else { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "cannot change PIN: non supported login type: %i", login_user); + sc_log(context, "cannot change PIN: non supported login type: %i", login_user); return CKR_FUNCTION_NOT_SUPPORTED; } - sc_debug(context, SC_LOG_DEBUG_NORMAL, "PIN change returns %d\n", rc); + sc_log(context, "PIN change returns %d\n", rc); return sc_to_cryptoki_error(rc, "C_SetPIN"); } @@ -1356,7 +1357,7 @@ static CK_RV pkcs15_init_pin(struct sc_pkcs11_card *p11card, struct sc_pkcs15_auth_info *auth_info; int rc; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "pkcs15 init PIN: pin %p:%d; unblock style %i", + sc_log(context, "pkcs15 init PIN: pin %p:%d; unblock style %i", pPin, ulPinLen, sc_pkcs11_conf.pin_unblock_style); auth_info = slot_data_auth_info(slot->fw_data); @@ -1536,14 +1537,14 @@ static CK_RV pkcs15_create_private_key(struct sc_pkcs11_card *p11card, if (key_type == CKK_RSA) { if (!rsa->modulus.len || !rsa->exponent.len || !rsa->d.len || !rsa->p.len || !rsa->q.len) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Template to store the RSA key is incomplete"); + sc_log(context, "Template to store the RSA key is incomplete"); rv = CKR_TEMPLATE_INCOMPLETE; goto out; } } else if (key_type == CKK_GOSTR3410) { if (!gost->d.len) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Template to store the GOST key is incomplete"); + sc_log(context, "Template to store the GOST key is incomplete"); return CKR_ATTRIBUTE_VALUE_INVALID; } /* CKA_VALUE arrives in little endian form. pkcs15init framework expects it in a big endian one. */ @@ -1896,7 +1897,7 @@ get_X509_usage_privk(CK_ATTRIBUTE_PTR pTempl, CK_ULONG ulCount, unsigned long *x if (typ == CKA_DERIVE && *val) *x509_usage |= SC_PKCS15INIT_X509_KEY_AGREEMENT; if (typ == CKA_VERIFY || typ == CKA_WRAP || typ == CKA_ENCRYPT) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "get_X509_usage_privk(): invalid typ = 0x%0x\n", typ); + sc_log(context, "get_X509_usage_privk(): invalid typ = 0x%0x\n", typ); return CKR_ATTRIBUTE_TYPE_INVALID; } } @@ -1921,7 +1922,7 @@ get_X509_usage_pubk(CK_ATTRIBUTE_PTR pTempl, CK_ULONG ulCount, unsigned long *x5 if (typ == CKA_DERIVE && *val) *x509_usage |= SC_PKCS15INIT_X509_KEY_AGREEMENT; if (typ == CKA_SIGN || typ == CKA_UNWRAP || typ == CKA_DECRYPT) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "get_X509_usage_pubk(): invalid typ = 0x%0x\n", typ); + sc_log(context, "get_X509_usage_pubk(): invalid typ = 0x%0x\n", typ); return CKR_ATTRIBUTE_TYPE_INVALID; } } @@ -1991,7 +1992,7 @@ static CK_RV pkcs15_gen_keypair(struct sc_pkcs11_card *p11card, char priv_label[SC_PKCS15_MAX_LABEL_SIZE]; int rc, rv = CKR_OK; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Keypair generation, mech = 0x%0x\n", pMechanism->mechanism); + sc_log(context, "Keypair generation, mech = 0x%0x\n", pMechanism->mechanism); if (pMechanism->mechanism != CKM_RSA_PKCS_KEY_PAIR_GEN && pMechanism->mechanism != CKM_GOSTR3410_KEY_PAIR_GEN @@ -2098,20 +2099,20 @@ static CK_RV pkcs15_gen_keypair(struct sc_pkcs11_card *p11card, sc_pkcs15init_set_p15card(profile, fw_data->p15_card); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Try on-card key pair generation"); + sc_log(context, "Try on-card key pair generation"); rc = sc_pkcs15init_generate_key(fw_data->p15_card, profile, &keygen_args, keybits, &priv_key_obj); if (rc >= 0) { id = ((struct sc_pkcs15_prkey_info *) priv_key_obj->data)->id; rc = sc_pkcs15_find_pubkey_by_id(fw_data->p15_card, &id, &pub_key_obj); if (rc != 0) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "sc_pkcs15_find_pubkey_by_id returned %d\n", rc); + sc_log(context, "sc_pkcs15_find_pubkey_by_id returned %d\n", rc); rv = sc_to_cryptoki_error(rc, "C_GenerateKeyPair"); goto kpgen_done; } } else if (rc != SC_ERROR_NOT_SUPPORTED) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "sc_pkcs15init_generate_key returned %d\n", rc); + sc_log(context, "sc_pkcs15init_generate_key returned %d\n", rc); rv = sc_to_cryptoki_error(rc, "C_GenerateKeyPair"); goto kpgen_done; } @@ -2122,7 +2123,7 @@ static CK_RV pkcs15_gen_keypair(struct sc_pkcs11_card *p11card, if (rc == 0) rc = __pkcs15_create_pubkey_object(fw_data, pub_key_obj, &pub_any_obj); if (rc != 0) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "__pkcs15_create_pr/pubkey_object returned %d\n", rc); + sc_log(context, "__pkcs15_create_pr/pubkey_object returned %d\n", rc); rv = sc_to_cryptoki_error(rc, "C_GenerateKeyPair"); goto kpgen_done; } @@ -2626,7 +2627,7 @@ static CK_RV pkcs15_prkey_sign(struct sc_pkcs11_session *ses, void *obj, struct pkcs15_fw_data *fw_data = (struct pkcs15_fw_data *) ses->slot->card->fw_data; int rv, flags = 0; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Initiating signing operation, mechanism 0x%x.\n", + sc_log(context, "Initiating signing operation, mechanism 0x%x.\n", pMechanism->mechanism); /* See which of the alternative keys supports signing */ @@ -2691,7 +2692,7 @@ static CK_RV pkcs15_prkey_sign(struct sc_pkcs11_session *ses, void *obj, break; #endif default: - sc_debug(context, SC_LOG_DEBUG_NORMAL, "DEE - need EC for %d",pMechanism->mechanism); + sc_log(context, "DEE - need EC for %d",pMechanism->mechanism); return CKR_MECHANISM_INVALID; } @@ -2707,7 +2708,7 @@ static CK_RV pkcs15_prkey_sign(struct sc_pkcs11_session *ses, void *obj, } } - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Selected flags %X. Now computing signature for %d bytes. %d bytes reserved.\n", flags, ulDataLen, *pulDataLen); + sc_log(context, "Selected flags %X. Now computing signature for %d bytes. %d bytes reserved.\n", flags, ulDataLen, *pulDataLen); rv = sc_pkcs15_compute_signature(fw_data->p15_card, prkey->prv_p15obj, flags, @@ -2718,7 +2719,7 @@ static CK_RV pkcs15_prkey_sign(struct sc_pkcs11_session *ses, void *obj, sc_unlock(ses->slot->card->card); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Sign complete. Result %d.\n", rv); + sc_log(context, "Sign complete. Result %d.\n", rv); if (rv > 0) { *pulDataLen = rv; @@ -2739,7 +2740,7 @@ pkcs15_prkey_decrypt(struct sc_pkcs11_session *ses, void *obj, u8 decrypted[256]; /* FIXME: Will not work for keys above 2048 bits */ int buff_too_small, rv, flags = 0; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Initiating decryption.\n"); + sc_log(context, "Initiating decryption.\n"); /* See which of the alternative keys supports decrypt */ prkey = (struct pkcs15_prkey_object *) obj; @@ -2781,7 +2782,7 @@ pkcs15_prkey_decrypt(struct sc_pkcs11_session *ses, void *obj, sc_unlock(ses->slot->card->card); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Decryption complete. Result %d.\n", rv); + sc_log(context, "Decryption complete. Result %d.\n", rv); if (rv < 0) return sc_to_cryptoki_error(rv, "C_Decrypt"); @@ -3037,8 +3038,8 @@ static CK_RV data_value_to_attr(CK_ATTRIBUTE_PTR attr, struct sc_pkcs15_data *da if (!attr || !data) return CKR_ATTRIBUTE_VALUE_INVALID; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "data %p\n", data); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "data_len %i\n", data->data_len); + sc_log(context, "data %p\n", data); + sc_log(context, "data_len %i\n", data->data_len); check_attribute_buffer(attr, data->data_len); memcpy(attr->pValue, data->data, data->data_len); @@ -3583,7 +3584,7 @@ static int lock_card(struct pkcs15_fw_data *fw_data) int rc; if ((rc = sc_lock(fw_data->p15_card->card)) < 0) - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Failed to lock card (%d)\n", rc); + sc_log(context, "Failed to lock card (%d)\n", rc); else fw_data->locked++; @@ -3608,7 +3609,7 @@ static int reselect_app_df(sc_pkcs15_card_t *p15card) /* if the application df (of the pkcs15 application) is * specified select it */ sc_path_t *tpath = &p15card->file_app->path; - sc_debug(p15card->card->ctx, SC_LOG_DEBUG_NORMAL, "reselect application df\n"); + sc_log(p15card->card->ctx, "reselect application df\n"); r = sc_select_file(p15card->card, tpath, NULL); } return r; diff --git a/src/pkcs11/misc.c b/src/pkcs11/misc.c index ae881d3e..49445251 100644 --- a/src/pkcs11/misc.c +++ b/src/pkcs11/misc.c @@ -56,7 +56,7 @@ void strcpy_bp(u8 * dst, const char *src, size_t dstsize) static CK_RV sc_to_cryptoki_error_common(int rc) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "libopensc return value: %d (%s)\n", rc, sc_strerror(rc)); + sc_log(context, "libopensc return value: %d (%s)\n", rc, sc_strerror(rc)); switch (rc) { case SC_SUCCESS: return CKR_OK; @@ -133,8 +133,8 @@ CK_RV session_start_operation(struct sc_pkcs11_session * session, if (context == NULL) return CKR_CRYPTOKI_NOT_INITIALIZED; - SC_FUNC_CALLED(context, SC_LOG_DEBUG_NORMAL); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Session 0x%lx, type %d", session->handle, type); + LOG_FUNC_CALLED(context); + sc_log(context, "Session 0x%lx, type %d", session->handle, type); if (type < 0 || type >= SC_PKCS11_OPERATION_MAX) return CKR_ARGUMENTS_BAD; @@ -155,7 +155,7 @@ CK_RV session_get_operation(struct sc_pkcs11_session * session, int type, sc_pkc { sc_pkcs11_operation_t *op; - SC_FUNC_CALLED(context, SC_LOG_DEBUG_NORMAL); + LOG_FUNC_CALLED(context); if (type < 0 || type >= SC_PKCS11_OPERATION_MAX) return CKR_ARGUMENTS_BAD; @@ -316,7 +316,7 @@ void load_pkcs11_parameters(struct sc_pkcs11_config *conf, sc_context_t * ctx) conf->create_puk_slot = scconf_get_bool(conf_block, "create_puk_slot", conf->create_puk_slot); conf->zero_ckaid_for_ca_certs = scconf_get_bool(conf_block, "zero_ckaid_for_ca_certs", conf->zero_ckaid_for_ca_certs); - sc_debug(ctx, SC_LOG_DEBUG_NORMAL, "PKCS#11 options: plug_and_play=%d max_virtual_slots=%d slots_per_card=%d " + sc_log(ctx, "PKCS#11 options: plug_and_play=%d max_virtual_slots=%d slots_per_card=%d " "hide_empty_tokens=%d lock_login=%d pin_unblock_style=%d zero_ckaid_for_ca_certs=%d", conf->plug_and_play, conf->max_virtual_slots, conf->slots_per_card, conf->hide_empty_tokens, conf->lock_login, conf->pin_unblock_style, diff --git a/src/pkcs11/openssl.c b/src/pkcs11/openssl.c index b560f335..6b5e0576 100644 --- a/src/pkcs11/openssl.c +++ b/src/pkcs11/openssl.c @@ -282,7 +282,7 @@ static CK_RV sc_pkcs11_openssl_md_final(sc_pkcs11_operation_t *op, EVP_MD_CTX *md_ctx = DIGEST_CTX(op); if (*pulDigestLen < (unsigned) EVP_MD_CTX_size(md_ctx)) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Provided buffer too small: %ul < %d", + sc_log(context, "Provided buffer too small: %ul < %d", *pulDigestLen, EVP_MD_CTX_size(md_ctx)); *pulDigestLen = EVP_MD_CTX_size(md_ctx); return CKR_BUFFER_TOO_SMALL; @@ -429,7 +429,7 @@ CK_RV sc_pkcs11_verify_data(const unsigned char *pubkey, int pubkey_len, else if (res == 0) return CKR_SIGNATURE_INVALID; else { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "EVP_VerifyFinal() returned %d\n", res); + sc_log(context, "EVP_VerifyFinal() returned %d\n", res); return CKR_GENERAL_ERROR; } } @@ -465,7 +465,7 @@ CK_RV sc_pkcs11_verify_data(const unsigned char *pubkey, int pubkey_len, RSA_free(rsa); if(rsa_outlen <= 0) { free(rsa_out); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "RSA_public_decrypt() returned %d\n", rsa_outlen); + sc_log(context, "RSA_public_decrypt() returned %d\n", rsa_outlen); return CKR_GENERAL_ERROR; } diff --git a/src/pkcs11/pkcs11-global.c b/src/pkcs11/pkcs11-global.c index 10a787c2..56529751 100644 --- a/src/pkcs11/pkcs11-global.c +++ b/src/pkcs11/pkcs11-global.c @@ -208,7 +208,7 @@ CK_RV C_Initialize(CK_VOID_PTR pInitArgs) #endif if (context != NULL) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_Initialize(): Cryptoki already initialized\n"); + sc_log(context, "C_Initialize(): Cryptoki already initialized\n"); return CKR_CRYPTOKI_ALREADY_INITIALIZED; } @@ -256,7 +256,7 @@ CK_RV C_Initialize(CK_VOID_PTR pInitArgs) out: if (context != NULL) - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_Initialize() = %s", lookup_enum ( RV_T, rv )); + sc_log(context, "C_Initialize() = %s", lookup_enum ( RV_T, rv )); if (rv != CKR_OK) { if (context != NULL) { @@ -287,7 +287,7 @@ CK_RV C_Finalize(CK_VOID_PTR pReserved) if (rv != CKR_OK) return rv; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_Finalize()"); + sc_log(context, "C_Finalize()"); /* cancel pending calls */ in_finalize = 1; @@ -326,7 +326,7 @@ CK_RV C_GetInfo(CK_INFO_PTR pInfo) if (rv != CKR_OK) return rv; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_GetInfo()"); + sc_log(context, "C_GetInfo()"); memset(pInfo, 0, sizeof(CK_INFO)); pInfo->cryptokiVersion.major = 2; @@ -371,7 +371,7 @@ CK_RV C_GetSlotList(CK_BBOOL tokenPresent, /* only slots with token prese return rv; } - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_GetSlotList(token=%d, %s)", tokenPresent, + sc_log(context, "C_GetSlotList(token=%d, %s)", tokenPresent, (pSlotList==NULL_PTR && sc_pkcs11_conf.plug_and_play)? "plug-n-play":"refresh"); /* Slot list can only change in v2.20 */ @@ -408,14 +408,14 @@ CK_RV C_GetSlotList(CK_BBOOL tokenPresent, /* only slots with token prese } if (pSlotList == NULL_PTR) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "was only a size inquiry (%d)\n", numMatches); + sc_log(context, "was only a size inquiry (%d)\n", numMatches); *pulCount = numMatches; rv = CKR_OK; goto out; } if (*pulCount < numMatches) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "buffer was too small (needed %d)\n", numMatches); + sc_log(context, "buffer was too small (needed %d)\n", numMatches); *pulCount = numMatches; rv = CKR_BUFFER_TOO_SMALL; goto out; @@ -425,7 +425,7 @@ CK_RV C_GetSlotList(CK_BBOOL tokenPresent, /* only slots with token prese *pulCount = numMatches; rv = CKR_OK; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "returned %d slots\n", numMatches); + sc_log(context, "returned %d slots\n", numMatches); out: if (found != NULL) { @@ -476,7 +476,7 @@ CK_RV C_GetSlotInfo(CK_SLOT_ID slotID, CK_SLOT_INFO_PTR pInfo) if (rv != CKR_OK) return rv; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_GetSlotInfo(0x%lx)", slotID); + sc_log(context, "C_GetSlotInfo(0x%lx)", slotID); rv = slot_get_slot(slotID, &slot); if (rv == CKR_OK){ @@ -498,7 +498,7 @@ CK_RV C_GetSlotInfo(CK_SLOT_ID slotID, CK_SLOT_INFO_PTR pInfo) if (rv == CKR_OK) memcpy(pInfo, &slot->slot_info, sizeof(CK_SLOT_INFO)); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_GetSlotInfo(0x%lx) = %s", slotID, lookup_enum ( RV_T, rv )); + sc_log(context, "C_GetSlotInfo(0x%lx) = %s", slotID, lookup_enum ( RV_T, rv )); sc_pkcs11_unlock(); return rv; } @@ -604,7 +604,7 @@ CK_RV C_WaitForSlotEvent(CK_FLAGS flags, /* blocking/nonblocking flag */ if (pReserved != NULL_PTR) return CKR_ARGUMENTS_BAD; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_WaitForSlotEvent(block=%d)", !(flags & CKF_DONT_BLOCK)); + sc_log(context, "C_WaitForSlotEvent(block=%d)", !(flags & CKF_DONT_BLOCK)); /* Not all pcsc-lite versions implement consistently used functions as they are */ /* FIXME: add proper checking into build to check correct pcsc-lite version for SCardStatusChange/SCardCancel */ if (!(flags & CKF_DONT_BLOCK)) @@ -625,7 +625,7 @@ CK_RV C_WaitForSlotEvent(CK_FLAGS flags, /* blocking/nonblocking flag */ goto out; again: - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_WaitForSlotEvent() reader_states:%p", reader_states); + sc_log(context, "C_WaitForSlotEvent() reader_states:%p", reader_states); sc_pkcs11_unlock(); r = sc_wait_for_event(context, mask, &found, &events, -1, &reader_states); if (sc_pkcs11_conf.plug_and_play && events & SC_EVENT_READER_ATTACHED) { @@ -648,7 +648,7 @@ again: return rv; if (r != SC_SUCCESS) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "sc_wait_for_event() returned %d\n", r); + sc_log(context, "sc_wait_for_event() returned %d\n", r); rv = sc_to_cryptoki_error(r, "C_WaitForSlotEvent"); goto out; } @@ -665,11 +665,11 @@ out: /* Free allocated readers states holder */ if (reader_states) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "free reader states"); + sc_log(context, "free reader states"); sc_wait_for_event(context, 0, NULL, NULL, -1, &reader_states); } - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_WaitForSlotEvent() = %s, event in 0x%lx", lookup_enum (RV_T, rv), *pSlot); + sc_log(context, "C_WaitForSlotEvent() = %s, event in 0x%lx", lookup_enum (RV_T, rv), *pSlot); sc_pkcs11_unlock(); return rv; } diff --git a/src/pkcs11/pkcs11-object.c b/src/pkcs11/pkcs11-object.c index 08b307c7..af725432 100644 --- a/src/pkcs11/pkcs11-object.c +++ b/src/pkcs11/pkcs11-object.c @@ -56,7 +56,7 @@ static void sc_find_release(sc_pkcs11_operation_t *operation) struct sc_pkcs11_find_operation *fop = (struct sc_pkcs11_find_operation *)operation; - sc_debug(context, SC_LOG_DEBUG_NORMAL,"freeing %d handles used %d at %p", + sc_log(context,"freeing %d handles used %d at %p", fop->allocated_handles, fop->num_handles, fop->handles); if (fop->handles) { free(fop->handles); @@ -96,7 +96,7 @@ CK_RV C_CreateObject(CK_SESSION_HANDLE hSession, /* the session's handle */ rv = sc_pkcs11_lock(); if (rv != CKR_OK) return rv; - SC_FUNC_CALLED(context, SC_LOG_DEBUG_VERBOSE); + LOG_FUNC_CALLED(context); dump_template(SC_LOG_DEBUG_NORMAL, "C_CreateObject()", pTemplate, ulCount); @@ -120,7 +120,7 @@ CK_RV C_CreateObject(CK_SESSION_HANDLE hSession, /* the session's handle */ pTemplate, ulCount, phObject); out: sc_pkcs11_unlock(); - SC_FUNC_RETURN(context, SC_LOG_DEBUG_VERBOSE, rv); + LOG_FUNC_RETURN(context, rv); } CK_RV C_CopyObject(CK_SESSION_HANDLE hSession, /* the session's handle */ @@ -143,7 +143,7 @@ CK_RV C_DestroyObject(CK_SESSION_HANDLE hSession, /* the session's handle */ if (rv != CKR_OK) return rv; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_DestroyObject(hSession=0x%lx, hObject=0x%lx)", hSession, hObject); + sc_log(context, "C_DestroyObject(hSession=0x%lx, hObject=0x%lx)", hSession, hObject); rv = get_object_from_session(hSession, hObject, &session, &object); if (rv != CKR_OK) @@ -231,7 +231,7 @@ CK_RV C_GetAttributeValue(CK_SESSION_HANDLE hSession, /* the session's handle */ } } -out: sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_GetAttributeValue(hSession=0x%lx, hObject=0x%lx) = %s", +out: sc_log(context, "C_GetAttributeValue(hSession=0x%lx, hObject=0x%lx) = %s", hSession, hObject, lookup_enum ( RV_T, rv )); sc_pkcs11_unlock(); return rv; @@ -304,7 +304,7 @@ CK_RV C_FindObjectsInit(CK_SESSION_HANDLE hSession, /* the session's handle */ if (rv != CKR_OK) goto out; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_FindObjectsInit(slot = %d)\n", session->slot->id); + sc_log(context, "C_FindObjectsInit(slot = %d)\n", session->slot->id); dump_template(SC_LOG_DEBUG_NORMAL, "C_FindObjectsInit()", pTemplate, ulCount); rv = session_start_operation(session, SC_PKCS11_OPERATION_FIND, @@ -326,15 +326,14 @@ CK_RV C_FindObjectsInit(CK_SESSION_HANDLE hSession, /* the session's handle */ /* For each object in token do */ for (i=0; iobjects); i++) { object = (struct sc_pkcs11_object *)list_get_at(&slot->objects, i); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Object with handle 0x%lx", object->handle); + sc_log(context, "Object with handle 0x%lx", object->handle); /* User not logged in and private object? */ if (hide_private) { if (object->ops->get_attribute(session, object, &private_attribute) != CKR_OK) continue; if (is_private) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, - "Object %d/%d: Private object and not logged in.\n", + sc_log(context, "Object %d/%d: Private object and not logged in.", slot->id, object->handle); continue; } @@ -345,26 +344,24 @@ CK_RV C_FindObjectsInit(CK_SESSION_HANDLE hSession, /* the session's handle */ for (j = 0; j < ulCount; j++) { rv = object->ops->cmp_attribute(session, object, &pTemplate[j]); if (rv == 0) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, - "Object %d/%d: Attribute 0x%x does NOT match.\n", + sc_log(context, "Object %d/%d: Attribute 0x%x does NOT match.", slot->id, object->handle, pTemplate[j].type); match = 0; break; } if (context->debug >= 4) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Object %d/%d: Attribute 0x%x matches.\n", + sc_log(context, "Object %d/%d: Attribute 0x%x matches.", slot->id, object->handle, pTemplate[j].type); } } if (match) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Object %d/%d matches\n", slot->id, object->handle); + sc_log(context, "Object %d/%d matches\n", slot->id, object->handle); /* Realloc handles - remove restriction on only 32 matching objects -dee */ if (operation->num_handles >= operation->allocated_handles) { operation->allocated_handles += SC_PKCS11_FIND_INC_HANDLES; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "realloc for %d handles", - operation->allocated_handles); + sc_log(context, "realloc for %d handles", operation->allocated_handles); operation->handles = realloc(operation->handles, sizeof(CK_OBJECT_HANDLE) * operation->allocated_handles); if (operation->handles == NULL) { @@ -377,7 +374,7 @@ CK_RV C_FindObjectsInit(CK_SESSION_HANDLE hSession, /* the session's handle */ } rv = CKR_OK; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "%d matching objects\n", operation->num_handles); + sc_log(context, "%d matching objects\n", operation->num_handles); out: sc_pkcs11_unlock(); return rv; @@ -464,12 +461,12 @@ CK_RV C_DigestInit(CK_SESSION_HANDLE hSession, /* the session's handle */ if (rv != CKR_OK) return rv; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_DigestInit(hSession=0x%lx)", hSession); + sc_log(context, "C_DigestInit(hSession=0x%lx)", hSession); rv = get_session(hSession, &session); if (rv == CKR_OK) rv = sc_pkcs11_md_init(session, pMechanism); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_DigestInit() = %s", lookup_enum ( RV_T, rv )); + sc_log(context, "C_DigestInit() = %s", lookup_enum ( RV_T, rv )); sc_pkcs11_unlock(); return rv; } @@ -487,7 +484,7 @@ CK_RV C_Digest(CK_SESSION_HANDLE hSession, /* the session's handle */ if (rv != CKR_OK) return rv; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_Digest(hSession=0x%lx)", hSession); + sc_log(context, "C_Digest(hSession=0x%lx)", hSession); rv = get_session(hSession, &session); if (rv != CKR_OK) goto out; @@ -496,7 +493,7 @@ CK_RV C_Digest(CK_SESSION_HANDLE hSession, /* the session's handle */ if (rv == CKR_OK) rv = sc_pkcs11_md_final(session, pDigest, pulDigestLen); -out: sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_Digest() = %s", lookup_enum ( RV_T, rv )); +out: sc_log(context, "C_Digest() = %s", lookup_enum ( RV_T, rv )); sc_pkcs11_unlock(); return rv; } @@ -516,7 +513,7 @@ CK_RV C_DigestUpdate(CK_SESSION_HANDLE hSession, /* the session's handle */ if (rv == CKR_OK) rv = sc_pkcs11_md_update(session, pPart, ulPartLen); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_DigestUpdate() == %s", lookup_enum ( RV_T, rv )); + sc_log(context, "C_DigestUpdate() == %s", lookup_enum ( RV_T, rv )); sc_pkcs11_unlock(); return rv; } @@ -542,7 +539,7 @@ CK_RV C_DigestFinal(CK_SESSION_HANDLE hSession, /* the session's handle */ if (rv == CKR_OK) rv = sc_pkcs11_md_final(session, pDigest, pulDigestLen); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_DigestFinal() = %s", lookup_enum ( RV_T, rv )); + sc_log(context, "C_DigestFinal() = %s", lookup_enum ( RV_T, rv )); sc_pkcs11_unlock(); return rv; } @@ -591,7 +588,7 @@ CK_RV C_SignInit(CK_SESSION_HANDLE hSession, /* the session's handle */ rv = sc_pkcs11_sign_init(session, pMechanism, object, key_type); -out: sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_SignInit() = %s", lookup_enum ( RV_T, rv )); +out: sc_log(context, "C_SignInit() = %s", lookup_enum ( RV_T, rv )); sc_pkcs11_unlock(); return rv; } @@ -632,7 +629,7 @@ CK_RV C_Sign(CK_SESSION_HANDLE hSession, /* the session's handle */ if (rv == CKR_OK) rv = sc_pkcs11_sign_final(session, pSignature, pulSignatureLen); -out: sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_Sign() = %s", lookup_enum ( RV_T, rv )); +out: sc_log(context, "C_Sign() = %s", lookup_enum ( RV_T, rv )); sc_pkcs11_unlock(); return rv; } @@ -652,7 +649,7 @@ CK_RV C_SignUpdate(CK_SESSION_HANDLE hSession, /* the session's handle */ if (rv == CKR_OK) rv = sc_pkcs11_sign_update(session, pPart, ulPartLen); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_SignUpdate() = %s", lookup_enum ( RV_T, rv )); + sc_log(context, "C_SignUpdate() = %s", lookup_enum ( RV_T, rv )); sc_pkcs11_unlock(); return rv; } @@ -688,7 +685,7 @@ CK_RV C_SignFinal(CK_SESSION_HANDLE hSession, /* the session's handle */ rv = sc_pkcs11_sign_final(session, pSignature, pulSignatureLen); } -out: sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_SignFinal() = %s", lookup_enum ( RV_T, rv )); +out: sc_log(context, "C_SignFinal() = %s", lookup_enum ( RV_T, rv )); sc_pkcs11_unlock(); return rv; } @@ -740,11 +737,11 @@ CK_RV C_SignRecoverInit(CK_SESSION_HANDLE hSession, /* the session's handle */ /* XXX: need to tell the signature algorithm that we want * to recover the signature */ - sc_debug(context, SC_LOG_DEBUG_NORMAL, "SignRecover operation initialized\n"); + sc_log(context, "SignRecover operation initialized\n"); rv = sc_pkcs11_sign_init(session, pMechanism, object, key_type); -out: sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_SignRecoverInit() = %sn", lookup_enum ( RV_T, rv )); +out: sc_log(context, "C_SignRecoverInit() = %sn", lookup_enum ( RV_T, rv )); sc_pkcs11_unlock(); return rv; } @@ -834,7 +831,7 @@ CK_RV C_DecryptInit(CK_SESSION_HANDLE hSession, /* the session's handle */ rv = sc_pkcs11_decr_init(session, pMechanism, object, key_type); -out: sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_DecryptInit() = %s", lookup_enum ( RV_T, rv )); +out: sc_log(context, "C_DecryptInit() = %s", lookup_enum ( RV_T, rv )); sc_pkcs11_unlock(); return rv; } @@ -857,7 +854,7 @@ CK_RV C_Decrypt(CK_SESSION_HANDLE hSession, /* the session's handle */ rv = sc_pkcs11_decr(session, pEncryptedData, ulEncryptedDataLen, pData, pulDataLen); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_Decrypt() = %s", lookup_enum ( RV_T, rv )); + sc_log(context, "C_Decrypt() = %s", lookup_enum ( RV_T, rv )); sc_pkcs11_unlock(); return rv; } @@ -1094,7 +1091,7 @@ CK_RV C_VerifyInit(CK_SESSION_HANDLE hSession, /* the session's handle */ rv = sc_pkcs11_verif_init(session, pMechanism, object, key_type); -out: sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_VerifyInit() = %s", lookup_enum ( RV_T, rv )); +out: sc_log(context, "C_VerifyInit() = %s", lookup_enum ( RV_T, rv )); sc_pkcs11_unlock(); return rv; #endif @@ -1124,7 +1121,7 @@ CK_RV C_Verify(CK_SESSION_HANDLE hSession, /* the session's handle */ if (rv == CKR_OK) rv = sc_pkcs11_verif_final(session, pSignature, ulSignatureLen); -out: sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_Verify() = %s", lookup_enum ( RV_T, rv )); +out: sc_log(context, "C_Verify() = %s", lookup_enum ( RV_T, rv )); sc_pkcs11_unlock(); return rv; #endif @@ -1148,7 +1145,7 @@ CK_RV C_VerifyUpdate(CK_SESSION_HANDLE hSession, /* the session's handle */ if (rv == CKR_OK) rv = sc_pkcs11_verif_update(session, pPart, ulPartLen); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_VerifyUpdate() = %s", lookup_enum ( RV_T, rv )); + sc_log(context, "C_VerifyUpdate() = %s", lookup_enum ( RV_T, rv )); sc_pkcs11_unlock(); return rv; #endif @@ -1172,7 +1169,7 @@ CK_RV C_VerifyFinal(CK_SESSION_HANDLE hSession, /* the session's handle */ if (rv == CKR_OK) rv = sc_pkcs11_verif_final(session, pSignature, ulSignatureLen); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_VerifyFinal() = %s", lookup_enum ( RV_T, rv )); + sc_log(context, "C_VerifyFinal() = %s", lookup_enum ( RV_T, rv )); sc_pkcs11_unlock(); return rv; #endif diff --git a/src/pkcs11/pkcs11-session.c b/src/pkcs11/pkcs11-session.c index 6b28e557..ba7d1ba2 100644 --- a/src/pkcs11/pkcs11-session.c +++ b/src/pkcs11/pkcs11-session.c @@ -54,7 +54,7 @@ CK_RV C_OpenSession(CK_SLOT_ID slotID, /* the slot's ID */ if (rv != CKR_OK) return rv; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_OpenSession(0x%lx)", slotID); + sc_log(context, "C_OpenSession(0x%lx)", slotID); rv = slot_get_token(slotID, &slot); if (rv != CKR_OK) @@ -80,10 +80,10 @@ CK_RV C_OpenSession(CK_SLOT_ID slotID, /* the slot's ID */ session->handle = (CK_SESSION_HANDLE) session; /* cast a pointer to long */ list_append(&sessions, session); *phSession = session->handle; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_OpenSession handle: 0x%lx", session->handle); + sc_log(context, "C_OpenSession handle: 0x%lx", session->handle); out: - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_OpenSession() = %s", lookup_enum(RV_T, rv)); + sc_log(context, "C_OpenSession() = %s", lookup_enum(RV_T, rv)); sc_pkcs11_unlock(); return rv; } @@ -95,7 +95,7 @@ static CK_RV sc_pkcs11_close_session(CK_SESSION_HANDLE hSession) struct sc_pkcs11_slot *slot; struct sc_pkcs11_session *session; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "real C_CloseSession(0x%lx)", hSession); + sc_log(context, "real C_CloseSession(0x%lx)", hSession); session = list_seek(&sessions, &hSession); if (!session) @@ -111,7 +111,7 @@ static CK_RV sc_pkcs11_close_session(CK_SESSION_HANDLE hSession) } if (list_delete(&sessions, session) != 0) - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Could not delete session from list!"); + sc_log(context, "Could not delete session from list!"); free(session); return CKR_OK; } @@ -123,7 +123,7 @@ CK_RV sc_pkcs11_close_all_sessions(CK_SLOT_ID slotID) CK_RV rv = CKR_OK; struct sc_pkcs11_session *session; unsigned int i; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "real C_CloseAllSessions(0x%lx) %d", slotID, list_size(&sessions)); + sc_log(context, "real C_CloseAllSessions(0x%lx) %d", slotID, list_size(&sessions)); for (i = 0; i < list_size(&sessions); i++) { session = list_get_at(&sessions, i); if (session->slot->id == slotID) @@ -141,7 +141,7 @@ CK_RV C_CloseSession(CK_SESSION_HANDLE hSession) if (rv != CKR_OK) return rv; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_CloseSession(0x%lx)\n", hSession); + sc_log(context, "C_CloseSession(0x%lx)\n", hSession); rv = sc_pkcs11_close_session(hSession); @@ -158,7 +158,7 @@ CK_RV C_CloseAllSessions(CK_SLOT_ID slotID) if (rv != CKR_OK) return rv; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_CloseAllSessions(0x%lx)\n", slotID); + sc_log(context, "C_CloseAllSessions(0x%lx)\n", slotID); rv = slot_get_token(slotID, &slot); if (rv != CKR_OK) @@ -184,7 +184,7 @@ CK_RV C_GetSessionInfo(CK_SESSION_HANDLE hSession, /* the session's handle */ if (rv != CKR_OK) return rv; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_GetSessionInfo(0x%lx)", hSession); + sc_log(context, "C_GetSessionInfo(0x%lx)", hSession); session = list_seek(&sessions, &hSession); if (!session) { @@ -192,7 +192,7 @@ CK_RV C_GetSessionInfo(CK_SESSION_HANDLE hSession, /* the session's handle */ goto out; } - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_GetSessionInfo(slot 0x%lx).", session->slot->id); + sc_log(context, "C_GetSessionInfo(slot 0x%lx).", session->slot->id); pInfo->slotID = session->slot->id; pInfo->flags = session->flags; pInfo->ulDeviceError = 0; @@ -209,7 +209,7 @@ CK_RV C_GetSessionInfo(CK_SESSION_HANDLE hSession, /* the session's handle */ } out: - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_GetSessionInfo(0x%lx) = %s", hSession, lookup_enum(RV_T, rv)); + sc_log(context, "C_GetSessionInfo(0x%lx) = %s", hSession, lookup_enum(RV_T, rv)); sc_pkcs11_unlock(); return rv; } @@ -256,7 +256,7 @@ CK_RV C_Login(CK_SESSION_HANDLE hSession, /* the session's handle */ goto out; } - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_Login(0x%lx, %d)", hSession, userType); + sc_log(context, "C_Login(0x%lx, %d)", hSession, userType); slot = session->slot; @@ -306,7 +306,7 @@ CK_RV C_Logout(CK_SESSION_HANDLE hSession) goto out; } - sc_debug(context, SC_LOG_DEBUG_NORMAL, "C_Logout(0x%lx)", hSession); + sc_log(context, "C_Logout(0x%lx)", hSession); slot = session->slot; @@ -379,7 +379,7 @@ CK_RV C_SetPIN(CK_SESSION_HANDLE hSession, } slot = session->slot; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Changing PIN (session 0x%lx; login user %d)\n", hSession, + sc_log(context, "Changing PIN (session 0x%lx; login user %d)\n", hSession, slot->login_user); if (!(session->flags & CKF_RW_SESSION)) { diff --git a/src/pkcs11/slot.c b/src/pkcs11/slot.c index a4501a1c..c64ee7ee 100644 --- a/src/pkcs11/slot.c +++ b/src/pkcs11/slot.c @@ -87,7 +87,7 @@ CK_RV create_slot(sc_reader_t *reader) list_append(&virtual_slots, slot); slot->login_user = -1; slot->id = (CK_SLOT_ID) list_locate(&virtual_slots, slot); - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Creating slot with id 0x%lx", slot->id); + sc_log(context, "Creating slot with id 0x%lx", slot->id); list_init(&slot->objects); list_attributes_seeker(&slot->objects, object_list_seeker); @@ -115,7 +115,7 @@ CK_RV initialize_reader(sc_reader_t *reader) list = scconf_find_list(conf_block, "ignored_readers"); while (list != NULL) { if (strstr(reader->name, list->data) != NULL) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Ignoring reader \'%s\' because of \'%s\'\n", reader->name, list->data); + sc_log(context, "Ignoring reader \'%s\' because of \'%s\'\n", reader->name, list->data); return CKR_OK; } list = list->next; @@ -141,7 +141,7 @@ CK_RV card_removed(sc_reader_t * reader) unsigned int i; struct sc_pkcs11_card *card = NULL; /* Mark all slots as "token not present" */ - sc_debug(context, SC_LOG_DEBUG_NORMAL, "%s: card removed", reader->name); + sc_log(context, "%s: card removed", reader->name); for (i=0; i < list_size(&virtual_slots); i++) { @@ -185,22 +185,22 @@ CK_RV card_detect(sc_reader_t *reader) rv = CKR_OK; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "%s: Detecting smart card\n", reader->name); + sc_log(context, "%s: Detecting smart card\n", reader->name); /* Check if someone inserted a card */ again:rc = sc_detect_card_presence(reader); if (rc < 0) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "%s: failed, %s\n", reader->name, sc_strerror(rc)); + sc_log(context, "%s: failed, %s\n", reader->name, sc_strerror(rc)); return sc_to_cryptoki_error(rc, NULL); } if (rc == 0) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "%s: card absent\n", reader->name); + sc_log(context, "%s: card absent\n", reader->name); card_removed(reader); /* Release all resources */ return CKR_TOKEN_NOT_PRESENT; } /* If the card was changed, disconnect the current one */ if (rc & SC_READER_CARD_CHANGED) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "%s: Card changed\n", reader->name); + sc_log(context, "%s: Card changed\n", reader->name); /* The following should never happen - but if it * does we'll be stuck in an endless loop. * So better be fussy. @@ -221,7 +221,7 @@ CK_RV card_detect(sc_reader_t *reader) /* Detect the card if it's not known already */ if (p11card == NULL) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "%s: First seen the card ", reader->name); + sc_log(context, "%s: First seen the card ", reader->name); p11card = (struct sc_pkcs11_card *)calloc(1, sizeof(struct sc_pkcs11_card)); if (!p11card) return CKR_HOST_MEMORY; @@ -229,7 +229,7 @@ CK_RV card_detect(sc_reader_t *reader) } if (p11card->card == NULL) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "%s: Connecting ... ", reader->name); + sc_log(context, "%s: Connecting ... ", reader->name); rc = sc_connect_card(reader, &p11card->card); if (rc != SC_SUCCESS) return sc_to_cryptoki_error(rc, NULL); @@ -237,7 +237,7 @@ CK_RV card_detect(sc_reader_t *reader) /* Detect the framework */ if (p11card->framework == NULL) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "%s: Detecting Framework\n", reader->name); + sc_log(context, "%s: Detecting Framework\n", reader->name); for (i = 0; frameworks[i]; i++) { if (frameworks[i]->bind == NULL) @@ -251,14 +251,14 @@ CK_RV card_detect(sc_reader_t *reader) return CKR_TOKEN_NOT_RECOGNIZED; /* Initialize framework */ - sc_debug(context, SC_LOG_DEBUG_NORMAL, "%s: Detected framework %d. Creating tokens.\n", reader->name, i); + sc_log(context, "%s: Detected framework %d. Creating tokens.\n", reader->name, i); rv = frameworks[i]->create_tokens(p11card); if (rv != CKR_OK) return rv; p11card->framework = frameworks[i]; } - sc_debug(context, SC_LOG_DEBUG_NORMAL, "%s: Detection ended\n", reader->name); + sc_log(context, "%s: Detection ended\n", reader->name); return CKR_OK; } @@ -289,7 +289,7 @@ CK_RV slot_allocate(struct sc_pkcs11_slot ** slot, struct sc_pkcs11_card * card) } if (!tmp_slot || (i == list_size(&virtual_slots))) return CKR_FUNCTION_FAILED; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "Allocated slot 0x%lx for card in reader %s", tmp_slot->id, + sc_log(context, "Allocated slot 0x%lx for card in reader %s", tmp_slot->id, card->reader->name); tmp_slot->card = card; tmp_slot->events = SC_EVENT_CARD_INSERTED; @@ -325,7 +325,7 @@ CK_RV slot_get_token(CK_SLOT_ID id, struct sc_pkcs11_slot ** slot) } if (!((*slot)->slot_info.flags & CKF_TOKEN_PRESENT)) { - sc_debug(context, SC_LOG_DEBUG_NORMAL, "card detected, but slot not presenting token"); + sc_log(context, "card detected, but slot not presenting token"); return CKR_TOKEN_NOT_PRESENT; } return CKR_OK; @@ -337,7 +337,7 @@ CK_RV slot_token_removed(CK_SLOT_ID id) struct sc_pkcs11_slot *slot; struct sc_pkcs11_object *object; - sc_debug(context, SC_LOG_DEBUG_NORMAL, "slot_token_removed(0x%lx)", id); + sc_log(context, "slot_token_removed(0x%lx)", id); rv = slot_get_slot(id, &slot); if (rv != CKR_OK) return rv; @@ -374,24 +374,24 @@ CK_RV slot_token_removed(CK_SLOT_ID id) CK_RV slot_find_changed(CK_SLOT_ID_PTR idp, int mask) { unsigned int i; - SC_FUNC_CALLED(context, SC_LOG_DEBUG_NORMAL); + LOG_FUNC_CALLED(context); card_detect_all(); for (i=0; iid, (slot->slot_info.flags & CKF_TOKEN_PRESENT), slot->events); + sc_log(context, "slot 0x%lx token: %d events: 0x%02X",slot->id, (slot->slot_info.flags & CKF_TOKEN_PRESENT), slot->events); if ((slot->events & SC_EVENT_CARD_INSERTED) && !(slot->slot_info.flags & CKF_TOKEN_PRESENT)) { /* If a token has not been initialized, clear the inserted event */ slot->events &= ~SC_EVENT_CARD_INSERTED; } - sc_debug(context, SC_LOG_DEBUG_NORMAL, "mask: 0x%02X events: 0x%02X result: %d", mask, slot->events, (slot->events & mask)); + sc_log(context, "mask: 0x%02X events: 0x%02X result: %d", mask, slot->events, (slot->events & mask)); if (slot->events & mask) { slot->events &= ~mask; *idp = slot->id; - SC_FUNC_RETURN(context, SC_LOG_DEBUG_VERBOSE, CKR_OK); + LOG_FUNC_RETURN(context, CKR_OK); } } - SC_FUNC_RETURN(context, SC_LOG_DEBUG_VERBOSE, CKR_NO_EVENT); + LOG_FUNC_RETURN(context, CKR_NO_EVENT); }