From 1c0ef565f81ff655cbaecadc6c496c8b899b8162 Mon Sep 17 00:00:00 2001 From: Rajesh Nyamagoud Date: Tue, 4 May 2021 09:09:45 -0700 Subject: [PATCH 1/3] Added debug and error logs in hal apis. --- .../4.1/JavacardKeymaster4Device.cpp | 192 +++++++++++++++++- 1 file changed, 189 insertions(+), 3 deletions(-) diff --git a/HAL/keymaster/4.1/JavacardKeymaster4Device.cpp b/HAL/keymaster/4.1/JavacardKeymaster4Device.cpp index a7298172..6fb17e97 100644 --- a/HAL/keymaster/4.1/JavacardKeymaster4Device.cpp +++ b/HAL/keymaster/4.1/JavacardKeymaster4Device.cpp @@ -68,6 +68,13 @@ struct KM_AUTH_LIST_Delete { void operator()(KM_AUTH_LIST* p) { KM_AUTH_LIST_free(p); } }; +template +auto as_integer(Enumeration const value) + -> typename std::underlying_type::type +{ + return static_cast::type>(value); +} + enum class Instruction { // Keymaster commands INS_GENERATE_KEY_CMD = INS_END_KM_PROVISION_CMD+1, @@ -432,6 +439,7 @@ ErrorCode sendData(Instruction ins, std::vector& inData, std::vector cborData = array.encode(); errorCode = sendData(Instruction::INS_SET_VERSION_PATCHLEVEL_CMD, cborData, cborOutData); + LOG(DEBUG) << "INS_SET_VERSION_PATCHLEVEL_CMD status: " << as_integer(errorCode); if (ErrorCode::OK == errorCode) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx); + LOG(DEBUG) << "INS_SET_VERSION_PATCHLEVEL_CMD decodeData status: " << as_integer(errorCode); } if (ErrorCode::OK != errorCode) LOG(ERROR) << "Failed to set os_version, os_patchlevel and vendor_patchlevel err: " << (int32_t) errorCode; @@ -494,24 +504,31 @@ Return JavacardKeymaster4Device::getHardwareInfo(getHardwareInfo_cb _hidl_ hidl_string jcKeymasterAuthor; ErrorCode ret = sendData(Instruction::INS_GET_HW_INFO_CMD, input, resp); + LOG(DEBUG) << "INS_GET_HW_INFO_CMD status: " << as_integer(ret); + if (ret == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, ret) = decodeData(cborConverter_, std::vector(resp.begin(), resp.end()-2), false, oprCtx_); + LOG(DEBUG) << "INS_GET_HW_INFO_CMD decodeData status: " << as_integer(ret); if (item != nullptr) { std::vector temp; if(!cborConverter_.getUint64(item, 0, securityLevel) || !cborConverter_.getBinaryArray(item, 1, jcKeymasterName) || !cborConverter_.getBinaryArray(item, 2, jcKeymasterAuthor)) { + LOG(ERROR) << "Failed to decode cbor data of INS_GET_HW_INFO_CMD"; _hidl_cb(static_cast(securityLevel), jcKeymasterName, jcKeymasterAuthor); return Void(); } + } else { + LOG(ERROR) << "Failed to decode cbor data of INS_GET_HW_INFO_CMD"; } _hidl_cb(static_cast(securityLevel), jcKeymasterName, jcKeymasterAuthor); return Void(); } else { // It should not come here, but incase if for any reason SB keymaster fails to getHardwareInfo // return proper values from HAL. + LOG(ERROR) << "Failed to fetch getHardwareInfo from javacard"; _hidl_cb(SecurityLevel::STRONGBOX, JAVACARD_KEYMASTER_NAME, JAVACARD_KEYMASTER_AUTHOR); return Void(); } @@ -524,14 +541,19 @@ Return JavacardKeymaster4Device::getHmacSharingParameters(getHmacSharingPa HmacSharingParameters hmacSharingParameters; ErrorCode errorCode = ErrorCode::UNKNOWN_ERROR; errorCode = sendData(Instruction::INS_GET_HMAC_SHARING_PARAM_CMD, input, cborData); + LOG(DEBUG) << "INS_GET_HMAC_SHARING_PARAM_CMD status: " << as_integer(errorCode); if (ErrorCode::OK == errorCode) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborData.begin(), cborData.end()-2), true, oprCtx_); + LOG(DEBUG) << "INS_GET_HMAC_SHARING_PARAM_CMD decodeData status: " << as_integer(errorCode); if (item != nullptr) { if(!cborConverter_.getHmacSharingParameters(item, 1, hmacSharingParameters)) { + LOG(ERROR) << "Failed to convert cbor data of INS_GET_HMAC_SHARING_PARAM_CMD"; errorCode = ErrorCode::UNKNOWN_ERROR; } + } else { + LOG(ERROR) << "Failed to decode cbor data of INS_GET_HMAC_SHARING_PARAM_CMD"; } } #ifdef VTS_EMULATOR @@ -541,11 +563,14 @@ Return JavacardKeymaster4Device::getHmacSharingParameters(getHmacSharingPa */ else { auto response = softKm_->GetHmacSharingParameters(); + LOG(DEBUG) << "INS_GET_HMAC_SHARING_PARAM_CMD failed with javacard"; + LOG(DEBUG) << "Setting software keymaster hmac sharing parameters"; hmacSharingParameters.seed.setToExternal(const_cast(response.params.seed.data), response.params.seed.data_length); static_assert(sizeof(response.params.nonce) == hmacSharingParameters.nonce.size(), "Nonce sizes don't match"); memcpy(hmacSharingParameters.nonce.data(), response.params.nonce, hmacSharingParameters.nonce.size()); errorCode = legacy_enum_conversion(response.error); + LOG(DEBUG) << "INS_GET_HMAC_SHARING_PARAM_CMD softkm status: " << as_integer(errorCode); } #endif _hidl_cb(errorCode, hmacSharingParameters); @@ -590,17 +615,22 @@ Return JavacardKeymaster4Device::computeSharedHmac(const hidl_vec cborData = array.encode(); errorCode = sendData(Instruction::INS_COMPUTE_SHARED_HMAC_CMD, cborData, cborOutData); + LOG(DEBUG) << "INS_COMPUTE_SHARED_HMAC_CMD status: " << as_integer(errorCode); if (ErrorCode::OK == errorCode) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); + LOG(DEBUG) << "INS_COMPUTE_SHARED_HMAC_CMD decodeData status: " << as_integer(errorCode); if (item != nullptr) { std::vector bstr; if(!cborConverter_.getBinaryArray(item, 1, bstr)) { + LOG(ERROR) << "INS_COMPUTE_SHARED_HMAC_CMD failed to get sharing check value"; errorCode = ErrorCode::UNKNOWN_ERROR; } else { sharingCheck = bstr; } + } else { + LOG(ERROR) << "Failed to decode cbor data of INS_COMPUTE_SHARED_HMAC_CMD"; } } #ifdef VTS_EMULATOR @@ -621,9 +651,11 @@ Return JavacardKeymaster4Device::computeSharedHmac(const hidl_vecComputeSharedHmac(request); if (response.error == KM_ERROR_OK) sharingCheck = kmBlob2hidlVec(response.sharing_check); errorCode = legacy_enum_conversion(response.error); + LOG(DEBUG) << "INS_COMPUTE_SHARED_HMAC_CMD softkm status: " << as_integer(errorCode); } #endif _hidl_cb(errorCode, sharingCheck); @@ -632,6 +664,7 @@ Return JavacardKeymaster4Device::computeSharedHmac(const hidl_vec JavacardKeymaster4Device::verifyAuthorization(uint64_t , const hidl_vec& , const HardwareAuthToken& , verifyAuthorization_cb _hidl_cb) { VerificationToken verificationToken; + LOG(DEBUG) << "Verify authorizations UNIMPLEMENTED"; _hidl_cb(ErrorCode::UNIMPLEMENTED, verificationToken); return Void(); } @@ -647,10 +680,14 @@ Return JavacardKeymaster4Device::addRngEntropy(const hidl_vec cborData = array.encode(); errorCode = sendData(Instruction::INS_ADD_RNG_ENTROPY_CMD, cborData, cborOutData); + LOG(DEBUG) << "INS_ADD_RNG_ENTROPY_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); + LOG(DEBUG) << "INS_ADD_RNG_ENTROPY_CMD decodeData status: " << as_integer(errorCode); + } else { + LOG(ERROR) << "Error in INS_ADD_RNG_ENTROPY_CMD status: " << as_integer(errorCode); } return errorCode; } @@ -678,10 +715,12 @@ Return JavacardKeymaster4Device::generateKey(const hidl_vec& std::vector cborData = array.encode(); errorCode = sendData(Instruction::INS_GENERATE_KEY_CMD, cborData, cborOutData); + LOG(DEBUG) << "INS_GENERATE_KEY_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); + LOG(DEBUG) << "INS_GENERATE_KEY_CMD decodeData status: " << as_integer(errorCode); if (item != nullptr) { if(!cborConverter_.getBinaryArray(item, 1, keyBlob) || !cborConverter_.getKeyCharacteristics(item, 2, keyCharacteristics)) { @@ -690,8 +729,13 @@ Return JavacardKeymaster4Device::generateKey(const hidl_vec& keyCharacteristics.softwareEnforced.setToExternal(nullptr, 0); keyCharacteristics.hardwareEnforced.setToExternal(nullptr, 0); errorCode = ErrorCode::UNKNOWN_ERROR; + LOG(ERROR) << "INS_GENERATE_KEY_CMD error while generating key: " << as_integer(errorCode); } + } else { + LOG(ERROR) << "INS_GENERATE_KEY_CMD error in decodeData: " << as_integer(errorCode); } + } else { + LOG(ERROR) << "Error in INS_GENERATE_KEY_CMD status: " << as_integer(errorCode); } _hidl_cb(errorCode, keyBlob, keyCharacteristics); return Void(); @@ -707,12 +751,14 @@ Return JavacardKeymaster4Device::importKey(const hidl_vec& k cppbor::Array subArray; if(keyFormat != KeyFormat::PKCS8 && keyFormat != KeyFormat::RAW) { + LOG(DEBUG) << "INS_IMPORT_KEY_CMD unsupported key format " << as_integer(keyFormat); _hidl_cb(ErrorCode::UNSUPPORTED_KEY_FORMAT, keyBlob, keyCharacteristics); return Void(); } cborConverter_.addKeyparameters(array, keyParams); array.add(static_cast(KeyFormat::RAW)); //javacard accepts only RAW. if(ErrorCode::OK != (errorCode = prepareCborArrayFromKeyData(keyParams, keyFormat, keyData, subArray))) { + LOG(ERROR) << "INS_IMPORT_KEY_CMD Error in while creating cbor data from key data:" << as_integer(errorCode); _hidl_cb(errorCode, keyBlob, keyCharacteristics); return Void(); } @@ -723,11 +769,13 @@ Return JavacardKeymaster4Device::importKey(const hidl_vec& k std::vector cborData = array.encode(); errorCode = sendData(Instruction::INS_IMPORT_KEY_CMD, cborData, cborOutData); + LOG(DEBUG) << "INS_IMPORT_KEY_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); + LOG(DEBUG) << "INS_IMPORT_KEY_CMD decodeData status: " << as_integer(errorCode); if (item != nullptr) { if(!cborConverter_.getBinaryArray(item, 1, keyBlob) || !cborConverter_.getKeyCharacteristics(item, 2, keyCharacteristics)) { @@ -736,8 +784,13 @@ Return JavacardKeymaster4Device::importKey(const hidl_vec& k keyCharacteristics.softwareEnforced.setToExternal(nullptr, 0); keyCharacteristics.hardwareEnforced.setToExternal(nullptr, 0); errorCode = ErrorCode::UNKNOWN_ERROR; + LOG(ERROR) << "Error in INS_IMPORT_KEY_CMD status: " << as_integer(errorCode); } + } else { + LOG(ERROR) << "INS_IMPORT_KEY_CMD error in decodeData status: " << as_integer(errorCode); } + } else { + LOG(ERROR) << "Error in INS_IMPORT_KEY_CMD status: " << as_integer(errorCode); } _hidl_cb(errorCode, keyBlob, keyCharacteristics); return Void(); @@ -760,6 +813,7 @@ Return JavacardKeymaster4Device::importWrappedKey(const hidl_vec& if(ErrorCode::OK != (errorCode = parseWrappedKey(wrappedKeyData, iv, transitKey, secureKey, tag, authList, keyFormat, wrappedKeyDescription))) { + LOG(ERROR) << "INS_IMPORT_WRAPPED_KEY_CMD error while parsing wrapped key status: " << as_integer(errorCode); _hidl_cb(errorCode, keyBlob, keyCharacteristics); return Void(); } @@ -778,11 +832,13 @@ Return JavacardKeymaster4Device::importWrappedKey(const hidl_vec& std::vector cborData = array.encode(); errorCode = sendData(Instruction::INS_IMPORT_WRAPPED_KEY_CMD, cborData, cborOutData); + LOG(DEBUG) << "INS_IMPORT_WRAPPED_KEY_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); + LOG(DEBUG) << "INS_IMPORT_WRAPPED_KEY_CMD decodeData status: " << as_integer(errorCode); if (item != nullptr) { if(!cborConverter_.getBinaryArray(item, 1, keyBlob) || !cborConverter_.getKeyCharacteristics(item, 2, keyCharacteristics)) { @@ -791,8 +847,13 @@ Return JavacardKeymaster4Device::importWrappedKey(const hidl_vec& keyCharacteristics.softwareEnforced.setToExternal(nullptr, 0); keyCharacteristics.hardwareEnforced.setToExternal(nullptr, 0); errorCode = ErrorCode::UNKNOWN_ERROR; + LOG(ERROR) << "Error in INS_IMPORT_WRAPPED_KEY_CMD status: " << as_integer(errorCode); } + } else { + LOG(ERROR) << "INS_IMPORT_WRAPPED_KEY_CMD error in decodeData status: " << as_integer(errorCode); } + } else { + LOG(ERROR) << "Error in INS_IMPORT_WRAPPED_KEY_CMD status: " << as_integer(errorCode); } _hidl_cb(errorCode, keyBlob, keyCharacteristics); return Void(); @@ -811,17 +872,24 @@ Return JavacardKeymaster4Device::getKeyCharacteristics(const hidl_vec cborData = array.encode(); errorCode = sendData(Instruction::INS_GET_KEY_CHARACTERISTICS_CMD, cborData, cborOutData); + LOG(DEBUG) << "INS_GET_KEY_CHARACTERISTICS_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); + LOG(DEBUG) << "INS_GET_KEY_CHARACTERISTICS_CMD decodeData status: " << as_integer(errorCode); if (item != nullptr) { if(!cborConverter_.getKeyCharacteristics(item, 1, keyCharacteristics)) { keyCharacteristics.softwareEnforced.setToExternal(nullptr, 0); keyCharacteristics.hardwareEnforced.setToExternal(nullptr, 0); errorCode = ErrorCode::UNKNOWN_ERROR; + LOG(ERROR) << "Error in INS_GET_KEY_CHARACTERISTICS_CMD status: " << as_integer(errorCode); } + } else { + LOG(ERROR) << "INS_GET_KEY_CHARACTERISTICS_CMD error in decodeData status: " << as_integer(errorCode); } + } else { + LOG(ERROR) << "Error in INS_GET_KEY_CHARACTERISTICS_CMD status: " << as_integer(errorCode); } _hidl_cb(errorCode, keyCharacteristics); return Void(); @@ -838,6 +906,7 @@ Return JavacardKeymaster4Device::exportKey(KeyFormat exportFormat, const h }); if(errorCode != ErrorCode::OK) { + LOG(ERROR) << "Error in exportKey status: " << as_integer(errorCode); _hidl_cb(errorCode, resultKeyBlob); return Void(); } @@ -856,7 +925,9 @@ Return JavacardKeymaster4Device::exportKey(KeyFormat exportFormat, const h if (response.error == KM_ERROR_OK) { resultKeyBlob.setToExternal(response.key_data, response.key_data_length); } - _hidl_cb(legacy_enum_conversion(response.error), resultKeyBlob); + errorCode = legacy_enum_conversion(response.error); + LOG(DEBUG) << "exportKey status: " << as_integer(errorCode); + _hidl_cb(errorCode, resultKeyBlob); return Void(); } @@ -874,6 +945,7 @@ Return JavacardKeymaster4Device::attestKey(const hidl_vec& keyToA cborConverter_.addKeyparameters(array, attestParams); std::vector cborData = array.encode(); errorCode = sendData(Instruction::INS_ATTEST_KEY_CMD, cborData, cborOutData); + LOG(DEBUG) << "INS_ATTEST_KEY_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { std::vector> temp; @@ -884,31 +956,45 @@ Return JavacardKeymaster4Device::attestKey(const hidl_vec& keyToA if (item != nullptr) { if(!cborConverter_.getMultiBinaryArray(item, 1, temp)) { errorCode = ErrorCode::UNKNOWN_ERROR; + LOG(ERROR) << "Error in INS_ATTEST_KEY_CMD status: " << as_integer(errorCode); } else { cborData.clear(); cborOutData.clear(); errorCode = sendData(Instruction::INS_GET_CERT_CHAIN_CMD, cborData, cborOutData); + LOG(DEBUG) << "attestkey INS_GET_CERT_CHAIN_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); + LOG(DEBUG) << "attestkey INS_GET_CERT_CHAIN_CMD decodeData status: " << as_integer(errorCode); if (item != nullptr) { std::vector chain; if(!cborConverter_.getBinaryArray(item, 1, chain)) { errorCode = ErrorCode::UNKNOWN_ERROR; + LOG(ERROR) << "Error in attestkey INS_GET_CERT_CHAIN_CMD status: " << as_integer(errorCode); } else { if(ErrorCode::OK == (errorCode = getCertificateChain(chain, temp))) { certChain.resize(temp.size()); for(int i = 0; i < temp.size(); i++) { certChain[i] = temp[i]; } + } else { + LOG(ERROR) << "Error in attestkey getCertificateChain status: " << as_integer(errorCode); } } + } else { + LOG(ERROR) << "Error in attestkey INS_GET_CERT_CHAIN_CMD decodeData status: " << as_integer(errorCode); } + } else { + LOG(ERROR) << "Error in attest-key INS_GET_CERT_CHAIN_CMD status: " << as_integer(errorCode); } } + } else { + LOG(ERROR) << "INS_ATTEST_KEY_CMD error in decodeData status: " << as_integer(errorCode); } + } else { + LOG(ERROR) << "Error in INS_ATTEST_KEY_CMD status: " << as_integer(errorCode); } _hidl_cb(errorCode, certChain); return Void(); @@ -926,15 +1012,23 @@ Return JavacardKeymaster4Device::upgradeKey(const hidl_vec& keyBl std::vector cborData = array.encode(); errorCode = sendData(Instruction::INS_UPGRADE_KEY_CMD, cborData, cborOutData); + LOG(DEBUG) << "INS_UPGRADE_KEY_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); + LOG(DEBUG) << "INS_UPGRADE_KEY_CMD decodeData status: " << as_integer(errorCode); if (item != nullptr) { - if(!cborConverter_.getBinaryArray(item, 1, upgradedKeyBlob)) + if(!cborConverter_.getBinaryArray(item, 1, upgradedKeyBlob)) { errorCode = ErrorCode::UNKNOWN_ERROR; + LOG(ERROR) << "Error in INS_UPGRADE_KEY_CMD status: " << as_integer(errorCode); + } + } else { + LOG(ERROR) << "INS_UPGRADE_KEY_CMD error in decodeData status: " << as_integer(errorCode); } + } else { + LOG(ERROR) << "Error in INS_UPGRADE_KEY_CMD status: " << as_integer(errorCode); } _hidl_cb(errorCode, upgradedKeyBlob); return Void(); @@ -949,11 +1043,15 @@ Return JavacardKeymaster4Device::deleteKey(const hidl_vec& k array.add(std::vector(keyBlob)); std::vector cborData = array.encode(); errorCode = sendData(Instruction::INS_DELETE_KEY_CMD, cborData, cborOutData); + LOG(DEBUG) << "INS_DELETE_KEY_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); + LOG(DEBUG) << "INS_DELETE_KEY_CMD decodeData status: " << as_integer(errorCode); + } else { + LOG(ERROR) << "Error in INS_DELETE_KEY_CMD status: " << as_integer(errorCode); } return errorCode; } @@ -965,11 +1063,15 @@ Return JavacardKeymaster4Device::deleteAllKeys() { ErrorCode errorCode = ErrorCode::UNKNOWN_ERROR; errorCode = sendData(Instruction::INS_DELETE_ALL_KEYS_CMD, input, cborOutData); + LOG(DEBUG) << "INS_DELETE_ALL_KEYS_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); + LOG(DEBUG) << "INS_DELETE_ALL_KEYS_CMD decodeData status: " << as_integer(errorCode); + } else { + LOG(ERROR) << "Error in INS_DELETE_ALL_KEYS_CMD status: " << as_integer(errorCode); } return errorCode; } @@ -981,11 +1083,15 @@ Return JavacardKeymaster4Device::destroyAttestationIds() { ErrorCode errorCode = ErrorCode::UNKNOWN_ERROR; errorCode = sendData(Instruction::INS_DESTROY_ATT_IDS_CMD, input, cborOutData); + LOG(DEBUG) << "INS_DESTROY_ATT_IDS_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); + LOG(DEBUG) << "INS_DESTROY_ATT_IDS_CMD debug status: " << as_integer(errorCode); + } else { + LOG(ERROR) << "Error in INS_DESTROY_ATT_IDS_CMD status: " << as_integer(errorCode); } return errorCode; } @@ -998,12 +1104,14 @@ Return JavacardKeymaster4Device::begin(KeyPurpose purpose, const hidl_vec< uint64_t generatedOpHandle = 0; if(keyBlob.size() == 0) { + LOG(ERROR) << "Error in INS_BEGIN_OPERATION_CMD, keyblob size is 0"; _hidl_cb(ErrorCode::INVALID_ARGUMENT, resultParams, operationHandle); return Void(); } /* Asymmetric public key operations like RSA Verify, RSA Encrypt, ECDSA verify * are handled by softkeymaster. */ + LOG(DEBUG) << "INS_BEGIN_OPERATION_CMD purpose: " << as_integer(purpose); if (KeyPurpose::ENCRYPT == purpose || KeyPurpose::VERIFY == purpose) { BeginOperationRequest request; request.purpose = legacy_enum_conversion(purpose); @@ -1013,6 +1121,10 @@ Return JavacardKeymaster4Device::begin(KeyPurpose purpose, const hidl_vec< BeginOperationResponse response; /* For Symmetric key operation, the BeginOperation returns KM_ERROR_INCOMPATIBLE_ALGORITHM error. */ softKm_->BeginOperation(request, &response); + errorCode = legacy_enum_conversion(response.error); + LOG(DEBUG) << "INS_BEGIN_OPERATION_CMD softkm BeginOperation status: " << as_integer(errorCode); + if (errorCode != ErrorCode::OK) + LOG(ERROR) << "INS_BEGIN_OPERATION_CMD error in softkm BeginOperation status: " << as_integer(errorCode); if (response.error == KM_ERROR_OK) { resultParams = kmParamSet2Hidl(response.output_params); @@ -1023,8 +1135,11 @@ Return JavacardKeymaster4Device::begin(KeyPurpose purpose, const hidl_vec< * key - new operation handle * value - hal generated operation handle. */ - if (errorCode == ErrorCode::OK) + if (errorCode == ErrorCode::OK) { errorCode = createOprHandleEntry(response.op_handle, SW_KM_OPR, generatedOpHandle); + if (errorCode != ErrorCode::OK) + LOG(ERROR) << "INS_BEGIN_OPERATION_CMD error while creating new operation handle: " << as_integer(errorCode); + } _hidl_cb(errorCode, resultParams, generatedOpHandle); return Void(); } @@ -1061,28 +1176,40 @@ Return JavacardKeymaster4Device::begin(KeyPurpose purpose, const hidl_vec< errorCode = error; keyCharacteristics = keyChars; }); + LOG(DEBUG) << "INS_BEGIN_OPERATION_CMD getKeyCharacteristics status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { errorCode = ErrorCode::UNKNOWN_ERROR; if(getTag(keyCharacteristics.hardwareEnforced, Tag::ALGORITHM, param)) { errorCode = sendData(Instruction::INS_BEGIN_OPERATION_CMD, cborData, cborOutData); + LOG(DEBUG) << "INS_BEGIN_OPERATION_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); + LOG(DEBUG) << "INS_BEGIN_OPERATION_CMD decodeData status: " << as_integer(errorCode); if (item != nullptr) { if(!cborConverter_.getKeyParameters(item, 1, outParams) || !cborConverter_.getUint64(item, 2, operationHandle)) { errorCode = ErrorCode::UNKNOWN_ERROR; outParams.setToExternal(nullptr, 0); operationHandle = 0; + LOG(ERROR) << "Error in INS_BEGIN_OPERATION_CMD status: " << as_integer(errorCode); } else { /* Store the operationInfo */ oprCtx_->setOperationInfo(operationHandle, purpose, param.f.algorithm, inParams); } + } else { + LOG(ERROR) << "Error in INS_BEGIN_OPERATION_CMD decodeData status: " << as_integer(errorCode); } + } else { + LOG(ERROR) << "Error in INS_BEGIN_OPERATION_CMD status: " << as_integer(errorCode); } + } else { + LOG(ERROR) << "INS_BEGIN_OPERATION_CMD couldn't find tag: " << as_integer(Tag::ALGORITHM); } + } else { + LOG(ERROR) << "INS_BEGIN_OPERATION_CMD error in getKeyCharacteristics status: " << as_integer(errorCode); } /* Create a new operation handle and add a entry inside the operation table map with * key - new operation handle @@ -1090,6 +1217,9 @@ Return JavacardKeymaster4Device::begin(KeyPurpose purpose, const hidl_vec< */ if (ErrorCode::OK == errorCode) errorCode = createOprHandleEntry(operationHandle, SB_KM_OPR, generatedOpHandle); + else + LOG(ERROR) << "Error in INS_BEGIN_OPERATION_CMD status: " << as_integer(errorCode); + _hidl_cb(errorCode, outParams, generatedOpHandle); return Void(); } @@ -1111,6 +1241,7 @@ Return JavacardKeymaster4Device::update(uint64_t halGeneratedOprHandle, co if (!isStrongboxOperation(halGeneratedOprHandle)) { /* SW keymaster (Public key operation) */ + LOG(DEBUG) << "INS_UPDATE_OPERATION_CMD - swkm operation "; UpdateOperationRequest request; request.op_handle = operationHandle; request.input.Reinitialize(input.data(), input.size()); @@ -1118,10 +1249,15 @@ Return JavacardKeymaster4Device::update(uint64_t halGeneratedOprHandle, co softKm_->UpdateOperation(request, &response); errorCode = legacy_enum_conversion(response.error); + LOG(DEBUG) << "INS_UPDATE_OPERATION_CMD - swkm update operation status: " + << as_integer(errorCode); if (response.error == KM_ERROR_OK) { inputConsumed = response.input_consumed; outParams = kmParamSet2Hidl(response.output_params); output = kmBuffer2hidlVec(response.output); + } else { + LOG(ERROR) << "INS_UPDATE_OPERATION_CMD - error swkm update operation status: " + << as_integer(errorCode); } } else { /* Strongbox Keymaster operation */ @@ -1141,10 +1277,13 @@ Return JavacardKeymaster4Device::update(uint64_t halGeneratedOprHandle, co //ASSOCIATED_DATA present in KeyParameters. Then we need to make a call to javacard Applet. if(data.size() == 0 && !findTag(inParams, Tag::ASSOCIATED_DATA)) { //Return OK, since this is not error case. + LOG(DEBUG) << "sendDataCallback: data size is zero"; return ErrorCode::OK; } if(ErrorCode::OK != (errorCode = encodeParametersVerified(verificationToken, asn1ParamsVerified))) { + LOG(ERROR) << "sendDataCallback: error in encodeParametersVerified status: " + << as_integer(errorCode); return errorCode; } @@ -1157,11 +1296,15 @@ Return JavacardKeymaster4Device::update(uint64_t halGeneratedOprHandle, co std::vector cborData = array.encode(); errorCode = sendData(Instruction::INS_UPDATE_OPERATION_CMD, cborData, cborOutData); + LOG(DEBUG) << "sendDataCallback: INS_UPDATE_OPERATION_CMD status: " + << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); + LOG(DEBUG) << "sendDataCallback: INS_UPDATE_OPERATION_CMD decodeData status: " + << as_integer(errorCode); if (item != nullptr) { /*Ignore inputConsumed from javacard SE since HAL consumes all the input */ //cborConverter_.getUint64(item, 1, inputConsumed); @@ -1174,8 +1317,16 @@ Return JavacardKeymaster4Device::update(uint64_t halGeneratedOprHandle, co outParams.setToExternal(nullptr, 0); tempOut.clear(); errorCode = ErrorCode::UNKNOWN_ERROR; + LOG(ERROR) << "sendDataCallback: error in INS_UPDATE_OPERATION_CMD status: " + << as_integer(errorCode); } + } else { + LOG(ERROR) << "sendDataCallback: INS_UPDATE_OPERATION_CMD error in decodeData status: " + << as_integer(errorCode); } + } else { + LOG(ERROR) << "sendDataCallback: error in INS_UPDATE_OPERATION_CMD status: " + << as_integer(errorCode); } return errorCode; }; @@ -1185,12 +1336,15 @@ Return JavacardKeymaster4Device::update(uint64_t halGeneratedOprHandle, co inputConsumed = input.size(); output = tempOut; } + LOG(DEBUG) << "Update operation status: " << as_integer(errorCode); if(ErrorCode::OK != errorCode) { + LOG(ERROR) << "Error in update operation, status: " << as_integer(errorCode); abort(halGeneratedOprHandle); } } if(ErrorCode::OK != errorCode) { /* Delete the entry from operation table. */ + LOG(ERROR) << "Delete entry from operation table, status: " << as_integer(errorCode); deleteOprHandleEntry(halGeneratedOprHandle); } @@ -1215,6 +1369,7 @@ Return JavacardKeymaster4Device::finish(uint64_t halGeneratedOprHandle, co if (!isStrongboxOperation(halGeneratedOprHandle)) { /* SW keymaster (Public key operation) */ + LOG(DEBUG) << "FINISH - swkm operation "; FinishOperationRequest request; request.op_handle = operationHandle; request.input.Reinitialize(input.data(), input.size()); @@ -1224,10 +1379,13 @@ Return JavacardKeymaster4Device::finish(uint64_t halGeneratedOprHandle, co softKm_->FinishOperation(request, &response); errorCode = legacy_enum_conversion(response.error); + LOG(DEBUG) << "FINISH - swkm operation, status: " << as_integer(errorCode); if (response.error == KM_ERROR_OK) { outParams = kmParamSet2Hidl(response.output_params); output = kmBuffer2hidlVec(response.output); + } else { + LOG(ERROR) << "Error in finish operation, status: " << as_integer(errorCode); } } else { /* Strongbox Keymaster operation */ @@ -1249,6 +1407,7 @@ Return JavacardKeymaster4Device::finish(uint64_t halGeneratedOprHandle, co std::vector asn1ParamsVerified; if(ErrorCode::OK != (errorCode = encodeParametersVerified(verificationToken, asn1ParamsVerified))) { + LOG(ERROR) << "sendDataCallback: Error in encodeParametersVerified, status: " << as_integer(errorCode); return errorCode; } @@ -1260,6 +1419,7 @@ Return JavacardKeymaster4Device::finish(uint64_t halGeneratedOprHandle, co array.add(operationHandle); if(finish) { std::vector finishParams; + LOG(DEBUG) << "sendDataCallback: finish operation"; if(aadTag) { for(int i = 0; i < inParams.size(); i++) { if(inParams[i].tag != Tag::ASSOCIATED_DATA) @@ -1275,6 +1435,7 @@ Return JavacardKeymaster4Device::finish(uint64_t halGeneratedOprHandle, co keyParamPos = 1; outputPos = 2; } else { + LOG(DEBUG) << "sendDataCallback: update operation"; if(findTag(inParams, Tag::ASSOCIATED_DATA)) { aadTag = true; } @@ -1288,11 +1449,13 @@ Return JavacardKeymaster4Device::finish(uint64_t halGeneratedOprHandle, co cborConverter_.addVerificationToken(array, verificationToken, asn1ParamsVerified); std::vector cborData = array.encode(); errorCode = sendData(ins, cborData, cborOutData); + LOG(DEBUG) << "sendDataCallback: operation: " << as_integer(ins) << " status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); + LOG(DEBUG) << "sendDataCallback: operation: " << as_integer(ins) << " decodeData status: " << as_integer(errorCode); if (item != nullptr) { //There is a change that this finish callback may gets called multiple times if the input data size //is larger the MAX_ALLOWED_INPUT_SIZE (Refer OperationContext) so parse and get the outParams only @@ -1304,8 +1467,13 @@ Return JavacardKeymaster4Device::finish(uint64_t halGeneratedOprHandle, co outParams.setToExternal(nullptr, 0); tempOut.clear(); errorCode = ErrorCode::UNKNOWN_ERROR; + LOG(ERROR) << "sendDataCallback: error in operation: " << as_integer(ins) << " decodeData, status: " << as_integer(errorCode); } + } else { + LOG(ERROR) << "sendDataCallback: error in operation: " << as_integer(ins) << " status: " << as_integer(errorCode); } + } else { + LOG(ERROR) << "sendDataCallback: error in operation: " << as_integer(ins) << " status: " << as_integer(errorCode); } return errorCode; }; @@ -1314,12 +1482,14 @@ Return JavacardKeymaster4Device::finish(uint64_t halGeneratedOprHandle, co output = tempOut; } if (ErrorCode::OK != errorCode) { + LOG(ERROR) << "Error in finish operation, status: " << as_integer(errorCode); abort(halGeneratedOprHandle); } } /* Delete the entry from operation table. */ deleteOprHandleEntry(halGeneratedOprHandle); oprCtx_->clearOperationData(operationHandle); + LOG(DEBUG) << "finish operation, status: " << as_integer(errorCode); _hidl_cb(errorCode, outParams, output); return Void(); } @@ -1339,6 +1509,7 @@ Return JavacardKeymaster4Device::abort(uint64_t halGeneratedOprHandle softKm_->AbortOperation(request, &response); errorCode = legacy_enum_conversion(response.error); + LOG(DEBUG) << "swkm abort operation, status: " << as_integer(errorCode); if (response.error == KM_ERROR_INVALID_OPERATION_HANDLE) { cppbor::Array array; std::unique_ptr item; @@ -1349,12 +1520,18 @@ Return JavacardKeymaster4Device::abort(uint64_t halGeneratedOprHandle std::vector cborData = array.encode(); errorCode = sendData(Instruction::INS_ABORT_OPERATION_CMD, cborData, cborOutData); + LOG(DEBUG) << "INS_ABORT_OPERATION_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); + LOG(DEBUG) << "INS_ABORT_OPERATION_CMD decodeData status: " << as_integer(errorCode); + } else { + LOG(ERROR) << "Error in INS_ABORT_OPERATION_CMD, status: " << as_integer(errorCode); } + } else { + LOG(DEBUG) << "Error in swkm abort operation, status: " << as_integer(errorCode); } /* Delete the entry on this operationHandle */ oprCtx_->clearOperationData(operationHandle); @@ -1372,6 +1549,7 @@ Return<::android::hardware::keymaster::V4_1::ErrorCode> JavacardKeymaster4Device ErrorCode ret = ErrorCode::UNKNOWN_ERROR; if(ErrorCode::OK != (ret = encodeParametersVerified(verificationToken, asn1ParamsVerified))) { + LOG(DEBUG) << "INS_DEVICE_LOCKED_CMD: Error in encodeParametersVerified, status: " << as_integer(errorCode); return errorCode; } @@ -1381,11 +1559,15 @@ Return<::android::hardware::keymaster::V4_1::ErrorCode> JavacardKeymaster4Device std::vector cborData = array.encode(); ret = sendData(Instruction::INS_DEVICE_LOCKED_CMD, cborData, cborOutData); + LOG(DEBUG) << "INS_DEVICE_LOCKED_CMD status: " << as_integer(ret); if(ret == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData<::android::hardware::keymaster::V4_1::ErrorCode>( cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); + LOG(DEBUG) << "INS_DEVICE_LOCKED_CMD decodeData status: " << as_integer(errorCode); + } else { + LOG(ERROR) << "Error in INS_DEVICE_LOCKED_CMD, status: " << as_integer(ret); } return errorCode; } @@ -1398,11 +1580,15 @@ Return<::android::hardware::keymaster::V4_1::ErrorCode> JavacardKeymaster4Device ::android::hardware::keymaster::V4_1::ErrorCode errorCode = ::android::hardware::keymaster::V4_1::ErrorCode::UNKNOWN_ERROR; ErrorCode ret = sendData(Instruction::INS_EARLY_BOOT_ENDED_CMD, cborInput, cborOutData); + LOG(DEBUG) << "INS_EARLY_BOOT_ENDED_CMD status: " << as_integer(ret); if(ret == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData<::android::hardware::keymaster::V4_1::ErrorCode>( cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); + LOG(DEBUG) << "INS_EARLY_BOOT_ENDED_CMD decodeData status: " << as_integer(errorCode); + } else { + LOG(ERROR) << "Error in INS_EARLY_BOOT_ENDED_CMD, status: " << as_integer(ret); } return errorCode; } From d6071e0f04ef328fa03ee8cf28eee49d431f9e16 Mon Sep 17 00:00:00 2001 From: Rajesh Nyamagoud Date: Wed, 5 May 2021 13:46:25 -0700 Subject: [PATCH 2/3] Revert "Added debug and error logs in hal apis." This reverts commit 1c0ef565f81ff655cbaecadc6c496c8b899b8162. --- .../4.1/JavacardKeymaster4Device.cpp | 192 +----------------- 1 file changed, 3 insertions(+), 189 deletions(-) diff --git a/HAL/keymaster/4.1/JavacardKeymaster4Device.cpp b/HAL/keymaster/4.1/JavacardKeymaster4Device.cpp index 6fb17e97..a7298172 100644 --- a/HAL/keymaster/4.1/JavacardKeymaster4Device.cpp +++ b/HAL/keymaster/4.1/JavacardKeymaster4Device.cpp @@ -68,13 +68,6 @@ struct KM_AUTH_LIST_Delete { void operator()(KM_AUTH_LIST* p) { KM_AUTH_LIST_free(p); } }; -template -auto as_integer(Enumeration const value) - -> typename std::underlying_type::type -{ - return static_cast::type>(value); -} - enum class Instruction { // Keymaster commands INS_GENERATE_KEY_CMD = INS_END_KM_PROVISION_CMD+1, @@ -439,7 +432,6 @@ ErrorCode sendData(Instruction ins, std::vector& inData, std::vector cborData = array.encode(); errorCode = sendData(Instruction::INS_SET_VERSION_PATCHLEVEL_CMD, cborData, cborOutData); - LOG(DEBUG) << "INS_SET_VERSION_PATCHLEVEL_CMD status: " << as_integer(errorCode); if (ErrorCode::OK == errorCode) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx); - LOG(DEBUG) << "INS_SET_VERSION_PATCHLEVEL_CMD decodeData status: " << as_integer(errorCode); } if (ErrorCode::OK != errorCode) LOG(ERROR) << "Failed to set os_version, os_patchlevel and vendor_patchlevel err: " << (int32_t) errorCode; @@ -504,31 +494,24 @@ Return JavacardKeymaster4Device::getHardwareInfo(getHardwareInfo_cb _hidl_ hidl_string jcKeymasterAuthor; ErrorCode ret = sendData(Instruction::INS_GET_HW_INFO_CMD, input, resp); - LOG(DEBUG) << "INS_GET_HW_INFO_CMD status: " << as_integer(ret); - if (ret == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, ret) = decodeData(cborConverter_, std::vector(resp.begin(), resp.end()-2), false, oprCtx_); - LOG(DEBUG) << "INS_GET_HW_INFO_CMD decodeData status: " << as_integer(ret); if (item != nullptr) { std::vector temp; if(!cborConverter_.getUint64(item, 0, securityLevel) || !cborConverter_.getBinaryArray(item, 1, jcKeymasterName) || !cborConverter_.getBinaryArray(item, 2, jcKeymasterAuthor)) { - LOG(ERROR) << "Failed to decode cbor data of INS_GET_HW_INFO_CMD"; _hidl_cb(static_cast(securityLevel), jcKeymasterName, jcKeymasterAuthor); return Void(); } - } else { - LOG(ERROR) << "Failed to decode cbor data of INS_GET_HW_INFO_CMD"; } _hidl_cb(static_cast(securityLevel), jcKeymasterName, jcKeymasterAuthor); return Void(); } else { // It should not come here, but incase if for any reason SB keymaster fails to getHardwareInfo // return proper values from HAL. - LOG(ERROR) << "Failed to fetch getHardwareInfo from javacard"; _hidl_cb(SecurityLevel::STRONGBOX, JAVACARD_KEYMASTER_NAME, JAVACARD_KEYMASTER_AUTHOR); return Void(); } @@ -541,19 +524,14 @@ Return JavacardKeymaster4Device::getHmacSharingParameters(getHmacSharingPa HmacSharingParameters hmacSharingParameters; ErrorCode errorCode = ErrorCode::UNKNOWN_ERROR; errorCode = sendData(Instruction::INS_GET_HMAC_SHARING_PARAM_CMD, input, cborData); - LOG(DEBUG) << "INS_GET_HMAC_SHARING_PARAM_CMD status: " << as_integer(errorCode); if (ErrorCode::OK == errorCode) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborData.begin(), cborData.end()-2), true, oprCtx_); - LOG(DEBUG) << "INS_GET_HMAC_SHARING_PARAM_CMD decodeData status: " << as_integer(errorCode); if (item != nullptr) { if(!cborConverter_.getHmacSharingParameters(item, 1, hmacSharingParameters)) { - LOG(ERROR) << "Failed to convert cbor data of INS_GET_HMAC_SHARING_PARAM_CMD"; errorCode = ErrorCode::UNKNOWN_ERROR; } - } else { - LOG(ERROR) << "Failed to decode cbor data of INS_GET_HMAC_SHARING_PARAM_CMD"; } } #ifdef VTS_EMULATOR @@ -563,14 +541,11 @@ Return JavacardKeymaster4Device::getHmacSharingParameters(getHmacSharingPa */ else { auto response = softKm_->GetHmacSharingParameters(); - LOG(DEBUG) << "INS_GET_HMAC_SHARING_PARAM_CMD failed with javacard"; - LOG(DEBUG) << "Setting software keymaster hmac sharing parameters"; hmacSharingParameters.seed.setToExternal(const_cast(response.params.seed.data), response.params.seed.data_length); static_assert(sizeof(response.params.nonce) == hmacSharingParameters.nonce.size(), "Nonce sizes don't match"); memcpy(hmacSharingParameters.nonce.data(), response.params.nonce, hmacSharingParameters.nonce.size()); errorCode = legacy_enum_conversion(response.error); - LOG(DEBUG) << "INS_GET_HMAC_SHARING_PARAM_CMD softkm status: " << as_integer(errorCode); } #endif _hidl_cb(errorCode, hmacSharingParameters); @@ -615,22 +590,17 @@ Return JavacardKeymaster4Device::computeSharedHmac(const hidl_vec cborData = array.encode(); errorCode = sendData(Instruction::INS_COMPUTE_SHARED_HMAC_CMD, cborData, cborOutData); - LOG(DEBUG) << "INS_COMPUTE_SHARED_HMAC_CMD status: " << as_integer(errorCode); if (ErrorCode::OK == errorCode) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); - LOG(DEBUG) << "INS_COMPUTE_SHARED_HMAC_CMD decodeData status: " << as_integer(errorCode); if (item != nullptr) { std::vector bstr; if(!cborConverter_.getBinaryArray(item, 1, bstr)) { - LOG(ERROR) << "INS_COMPUTE_SHARED_HMAC_CMD failed to get sharing check value"; errorCode = ErrorCode::UNKNOWN_ERROR; } else { sharingCheck = bstr; } - } else { - LOG(ERROR) << "Failed to decode cbor data of INS_COMPUTE_SHARED_HMAC_CMD"; } } #ifdef VTS_EMULATOR @@ -651,11 +621,9 @@ Return JavacardKeymaster4Device::computeSharedHmac(const hidl_vecComputeSharedHmac(request); if (response.error == KM_ERROR_OK) sharingCheck = kmBlob2hidlVec(response.sharing_check); errorCode = legacy_enum_conversion(response.error); - LOG(DEBUG) << "INS_COMPUTE_SHARED_HMAC_CMD softkm status: " << as_integer(errorCode); } #endif _hidl_cb(errorCode, sharingCheck); @@ -664,7 +632,6 @@ Return JavacardKeymaster4Device::computeSharedHmac(const hidl_vec JavacardKeymaster4Device::verifyAuthorization(uint64_t , const hidl_vec& , const HardwareAuthToken& , verifyAuthorization_cb _hidl_cb) { VerificationToken verificationToken; - LOG(DEBUG) << "Verify authorizations UNIMPLEMENTED"; _hidl_cb(ErrorCode::UNIMPLEMENTED, verificationToken); return Void(); } @@ -680,14 +647,10 @@ Return JavacardKeymaster4Device::addRngEntropy(const hidl_vec cborData = array.encode(); errorCode = sendData(Instruction::INS_ADD_RNG_ENTROPY_CMD, cborData, cborOutData); - LOG(DEBUG) << "INS_ADD_RNG_ENTROPY_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); - LOG(DEBUG) << "INS_ADD_RNG_ENTROPY_CMD decodeData status: " << as_integer(errorCode); - } else { - LOG(ERROR) << "Error in INS_ADD_RNG_ENTROPY_CMD status: " << as_integer(errorCode); } return errorCode; } @@ -715,12 +678,10 @@ Return JavacardKeymaster4Device::generateKey(const hidl_vec& std::vector cborData = array.encode(); errorCode = sendData(Instruction::INS_GENERATE_KEY_CMD, cborData, cborOutData); - LOG(DEBUG) << "INS_GENERATE_KEY_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); - LOG(DEBUG) << "INS_GENERATE_KEY_CMD decodeData status: " << as_integer(errorCode); if (item != nullptr) { if(!cborConverter_.getBinaryArray(item, 1, keyBlob) || !cborConverter_.getKeyCharacteristics(item, 2, keyCharacteristics)) { @@ -729,13 +690,8 @@ Return JavacardKeymaster4Device::generateKey(const hidl_vec& keyCharacteristics.softwareEnforced.setToExternal(nullptr, 0); keyCharacteristics.hardwareEnforced.setToExternal(nullptr, 0); errorCode = ErrorCode::UNKNOWN_ERROR; - LOG(ERROR) << "INS_GENERATE_KEY_CMD error while generating key: " << as_integer(errorCode); } - } else { - LOG(ERROR) << "INS_GENERATE_KEY_CMD error in decodeData: " << as_integer(errorCode); } - } else { - LOG(ERROR) << "Error in INS_GENERATE_KEY_CMD status: " << as_integer(errorCode); } _hidl_cb(errorCode, keyBlob, keyCharacteristics); return Void(); @@ -751,14 +707,12 @@ Return JavacardKeymaster4Device::importKey(const hidl_vec& k cppbor::Array subArray; if(keyFormat != KeyFormat::PKCS8 && keyFormat != KeyFormat::RAW) { - LOG(DEBUG) << "INS_IMPORT_KEY_CMD unsupported key format " << as_integer(keyFormat); _hidl_cb(ErrorCode::UNSUPPORTED_KEY_FORMAT, keyBlob, keyCharacteristics); return Void(); } cborConverter_.addKeyparameters(array, keyParams); array.add(static_cast(KeyFormat::RAW)); //javacard accepts only RAW. if(ErrorCode::OK != (errorCode = prepareCborArrayFromKeyData(keyParams, keyFormat, keyData, subArray))) { - LOG(ERROR) << "INS_IMPORT_KEY_CMD Error in while creating cbor data from key data:" << as_integer(errorCode); _hidl_cb(errorCode, keyBlob, keyCharacteristics); return Void(); } @@ -769,13 +723,11 @@ Return JavacardKeymaster4Device::importKey(const hidl_vec& k std::vector cborData = array.encode(); errorCode = sendData(Instruction::INS_IMPORT_KEY_CMD, cborData, cborOutData); - LOG(DEBUG) << "INS_IMPORT_KEY_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); - LOG(DEBUG) << "INS_IMPORT_KEY_CMD decodeData status: " << as_integer(errorCode); if (item != nullptr) { if(!cborConverter_.getBinaryArray(item, 1, keyBlob) || !cborConverter_.getKeyCharacteristics(item, 2, keyCharacteristics)) { @@ -784,13 +736,8 @@ Return JavacardKeymaster4Device::importKey(const hidl_vec& k keyCharacteristics.softwareEnforced.setToExternal(nullptr, 0); keyCharacteristics.hardwareEnforced.setToExternal(nullptr, 0); errorCode = ErrorCode::UNKNOWN_ERROR; - LOG(ERROR) << "Error in INS_IMPORT_KEY_CMD status: " << as_integer(errorCode); } - } else { - LOG(ERROR) << "INS_IMPORT_KEY_CMD error in decodeData status: " << as_integer(errorCode); } - } else { - LOG(ERROR) << "Error in INS_IMPORT_KEY_CMD status: " << as_integer(errorCode); } _hidl_cb(errorCode, keyBlob, keyCharacteristics); return Void(); @@ -813,7 +760,6 @@ Return JavacardKeymaster4Device::importWrappedKey(const hidl_vec& if(ErrorCode::OK != (errorCode = parseWrappedKey(wrappedKeyData, iv, transitKey, secureKey, tag, authList, keyFormat, wrappedKeyDescription))) { - LOG(ERROR) << "INS_IMPORT_WRAPPED_KEY_CMD error while parsing wrapped key status: " << as_integer(errorCode); _hidl_cb(errorCode, keyBlob, keyCharacteristics); return Void(); } @@ -832,13 +778,11 @@ Return JavacardKeymaster4Device::importWrappedKey(const hidl_vec& std::vector cborData = array.encode(); errorCode = sendData(Instruction::INS_IMPORT_WRAPPED_KEY_CMD, cborData, cborOutData); - LOG(DEBUG) << "INS_IMPORT_WRAPPED_KEY_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); - LOG(DEBUG) << "INS_IMPORT_WRAPPED_KEY_CMD decodeData status: " << as_integer(errorCode); if (item != nullptr) { if(!cborConverter_.getBinaryArray(item, 1, keyBlob) || !cborConverter_.getKeyCharacteristics(item, 2, keyCharacteristics)) { @@ -847,13 +791,8 @@ Return JavacardKeymaster4Device::importWrappedKey(const hidl_vec& keyCharacteristics.softwareEnforced.setToExternal(nullptr, 0); keyCharacteristics.hardwareEnforced.setToExternal(nullptr, 0); errorCode = ErrorCode::UNKNOWN_ERROR; - LOG(ERROR) << "Error in INS_IMPORT_WRAPPED_KEY_CMD status: " << as_integer(errorCode); } - } else { - LOG(ERROR) << "INS_IMPORT_WRAPPED_KEY_CMD error in decodeData status: " << as_integer(errorCode); } - } else { - LOG(ERROR) << "Error in INS_IMPORT_WRAPPED_KEY_CMD status: " << as_integer(errorCode); } _hidl_cb(errorCode, keyBlob, keyCharacteristics); return Void(); @@ -872,24 +811,17 @@ Return JavacardKeymaster4Device::getKeyCharacteristics(const hidl_vec cborData = array.encode(); errorCode = sendData(Instruction::INS_GET_KEY_CHARACTERISTICS_CMD, cborData, cborOutData); - LOG(DEBUG) << "INS_GET_KEY_CHARACTERISTICS_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); - LOG(DEBUG) << "INS_GET_KEY_CHARACTERISTICS_CMD decodeData status: " << as_integer(errorCode); if (item != nullptr) { if(!cborConverter_.getKeyCharacteristics(item, 1, keyCharacteristics)) { keyCharacteristics.softwareEnforced.setToExternal(nullptr, 0); keyCharacteristics.hardwareEnforced.setToExternal(nullptr, 0); errorCode = ErrorCode::UNKNOWN_ERROR; - LOG(ERROR) << "Error in INS_GET_KEY_CHARACTERISTICS_CMD status: " << as_integer(errorCode); } - } else { - LOG(ERROR) << "INS_GET_KEY_CHARACTERISTICS_CMD error in decodeData status: " << as_integer(errorCode); } - } else { - LOG(ERROR) << "Error in INS_GET_KEY_CHARACTERISTICS_CMD status: " << as_integer(errorCode); } _hidl_cb(errorCode, keyCharacteristics); return Void(); @@ -906,7 +838,6 @@ Return JavacardKeymaster4Device::exportKey(KeyFormat exportFormat, const h }); if(errorCode != ErrorCode::OK) { - LOG(ERROR) << "Error in exportKey status: " << as_integer(errorCode); _hidl_cb(errorCode, resultKeyBlob); return Void(); } @@ -925,9 +856,7 @@ Return JavacardKeymaster4Device::exportKey(KeyFormat exportFormat, const h if (response.error == KM_ERROR_OK) { resultKeyBlob.setToExternal(response.key_data, response.key_data_length); } - errorCode = legacy_enum_conversion(response.error); - LOG(DEBUG) << "exportKey status: " << as_integer(errorCode); - _hidl_cb(errorCode, resultKeyBlob); + _hidl_cb(legacy_enum_conversion(response.error), resultKeyBlob); return Void(); } @@ -945,7 +874,6 @@ Return JavacardKeymaster4Device::attestKey(const hidl_vec& keyToA cborConverter_.addKeyparameters(array, attestParams); std::vector cborData = array.encode(); errorCode = sendData(Instruction::INS_ATTEST_KEY_CMD, cborData, cborOutData); - LOG(DEBUG) << "INS_ATTEST_KEY_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { std::vector> temp; @@ -956,45 +884,31 @@ Return JavacardKeymaster4Device::attestKey(const hidl_vec& keyToA if (item != nullptr) { if(!cborConverter_.getMultiBinaryArray(item, 1, temp)) { errorCode = ErrorCode::UNKNOWN_ERROR; - LOG(ERROR) << "Error in INS_ATTEST_KEY_CMD status: " << as_integer(errorCode); } else { cborData.clear(); cborOutData.clear(); errorCode = sendData(Instruction::INS_GET_CERT_CHAIN_CMD, cborData, cborOutData); - LOG(DEBUG) << "attestkey INS_GET_CERT_CHAIN_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); - LOG(DEBUG) << "attestkey INS_GET_CERT_CHAIN_CMD decodeData status: " << as_integer(errorCode); if (item != nullptr) { std::vector chain; if(!cborConverter_.getBinaryArray(item, 1, chain)) { errorCode = ErrorCode::UNKNOWN_ERROR; - LOG(ERROR) << "Error in attestkey INS_GET_CERT_CHAIN_CMD status: " << as_integer(errorCode); } else { if(ErrorCode::OK == (errorCode = getCertificateChain(chain, temp))) { certChain.resize(temp.size()); for(int i = 0; i < temp.size(); i++) { certChain[i] = temp[i]; } - } else { - LOG(ERROR) << "Error in attestkey getCertificateChain status: " << as_integer(errorCode); } } - } else { - LOG(ERROR) << "Error in attestkey INS_GET_CERT_CHAIN_CMD decodeData status: " << as_integer(errorCode); } - } else { - LOG(ERROR) << "Error in attest-key INS_GET_CERT_CHAIN_CMD status: " << as_integer(errorCode); } } - } else { - LOG(ERROR) << "INS_ATTEST_KEY_CMD error in decodeData status: " << as_integer(errorCode); } - } else { - LOG(ERROR) << "Error in INS_ATTEST_KEY_CMD status: " << as_integer(errorCode); } _hidl_cb(errorCode, certChain); return Void(); @@ -1012,23 +926,15 @@ Return JavacardKeymaster4Device::upgradeKey(const hidl_vec& keyBl std::vector cborData = array.encode(); errorCode = sendData(Instruction::INS_UPGRADE_KEY_CMD, cborData, cborOutData); - LOG(DEBUG) << "INS_UPGRADE_KEY_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); - LOG(DEBUG) << "INS_UPGRADE_KEY_CMD decodeData status: " << as_integer(errorCode); if (item != nullptr) { - if(!cborConverter_.getBinaryArray(item, 1, upgradedKeyBlob)) { + if(!cborConverter_.getBinaryArray(item, 1, upgradedKeyBlob)) errorCode = ErrorCode::UNKNOWN_ERROR; - LOG(ERROR) << "Error in INS_UPGRADE_KEY_CMD status: " << as_integer(errorCode); - } - } else { - LOG(ERROR) << "INS_UPGRADE_KEY_CMD error in decodeData status: " << as_integer(errorCode); } - } else { - LOG(ERROR) << "Error in INS_UPGRADE_KEY_CMD status: " << as_integer(errorCode); } _hidl_cb(errorCode, upgradedKeyBlob); return Void(); @@ -1043,15 +949,11 @@ Return JavacardKeymaster4Device::deleteKey(const hidl_vec& k array.add(std::vector(keyBlob)); std::vector cborData = array.encode(); errorCode = sendData(Instruction::INS_DELETE_KEY_CMD, cborData, cborOutData); - LOG(DEBUG) << "INS_DELETE_KEY_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); - LOG(DEBUG) << "INS_DELETE_KEY_CMD decodeData status: " << as_integer(errorCode); - } else { - LOG(ERROR) << "Error in INS_DELETE_KEY_CMD status: " << as_integer(errorCode); } return errorCode; } @@ -1063,15 +965,11 @@ Return JavacardKeymaster4Device::deleteAllKeys() { ErrorCode errorCode = ErrorCode::UNKNOWN_ERROR; errorCode = sendData(Instruction::INS_DELETE_ALL_KEYS_CMD, input, cborOutData); - LOG(DEBUG) << "INS_DELETE_ALL_KEYS_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); - LOG(DEBUG) << "INS_DELETE_ALL_KEYS_CMD decodeData status: " << as_integer(errorCode); - } else { - LOG(ERROR) << "Error in INS_DELETE_ALL_KEYS_CMD status: " << as_integer(errorCode); } return errorCode; } @@ -1083,15 +981,11 @@ Return JavacardKeymaster4Device::destroyAttestationIds() { ErrorCode errorCode = ErrorCode::UNKNOWN_ERROR; errorCode = sendData(Instruction::INS_DESTROY_ATT_IDS_CMD, input, cborOutData); - LOG(DEBUG) << "INS_DESTROY_ATT_IDS_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); - LOG(DEBUG) << "INS_DESTROY_ATT_IDS_CMD debug status: " << as_integer(errorCode); - } else { - LOG(ERROR) << "Error in INS_DESTROY_ATT_IDS_CMD status: " << as_integer(errorCode); } return errorCode; } @@ -1104,14 +998,12 @@ Return JavacardKeymaster4Device::begin(KeyPurpose purpose, const hidl_vec< uint64_t generatedOpHandle = 0; if(keyBlob.size() == 0) { - LOG(ERROR) << "Error in INS_BEGIN_OPERATION_CMD, keyblob size is 0"; _hidl_cb(ErrorCode::INVALID_ARGUMENT, resultParams, operationHandle); return Void(); } /* Asymmetric public key operations like RSA Verify, RSA Encrypt, ECDSA verify * are handled by softkeymaster. */ - LOG(DEBUG) << "INS_BEGIN_OPERATION_CMD purpose: " << as_integer(purpose); if (KeyPurpose::ENCRYPT == purpose || KeyPurpose::VERIFY == purpose) { BeginOperationRequest request; request.purpose = legacy_enum_conversion(purpose); @@ -1121,10 +1013,6 @@ Return JavacardKeymaster4Device::begin(KeyPurpose purpose, const hidl_vec< BeginOperationResponse response; /* For Symmetric key operation, the BeginOperation returns KM_ERROR_INCOMPATIBLE_ALGORITHM error. */ softKm_->BeginOperation(request, &response); - errorCode = legacy_enum_conversion(response.error); - LOG(DEBUG) << "INS_BEGIN_OPERATION_CMD softkm BeginOperation status: " << as_integer(errorCode); - if (errorCode != ErrorCode::OK) - LOG(ERROR) << "INS_BEGIN_OPERATION_CMD error in softkm BeginOperation status: " << as_integer(errorCode); if (response.error == KM_ERROR_OK) { resultParams = kmParamSet2Hidl(response.output_params); @@ -1135,11 +1023,8 @@ Return JavacardKeymaster4Device::begin(KeyPurpose purpose, const hidl_vec< * key - new operation handle * value - hal generated operation handle. */ - if (errorCode == ErrorCode::OK) { + if (errorCode == ErrorCode::OK) errorCode = createOprHandleEntry(response.op_handle, SW_KM_OPR, generatedOpHandle); - if (errorCode != ErrorCode::OK) - LOG(ERROR) << "INS_BEGIN_OPERATION_CMD error while creating new operation handle: " << as_integer(errorCode); - } _hidl_cb(errorCode, resultParams, generatedOpHandle); return Void(); } @@ -1176,40 +1061,28 @@ Return JavacardKeymaster4Device::begin(KeyPurpose purpose, const hidl_vec< errorCode = error; keyCharacteristics = keyChars; }); - LOG(DEBUG) << "INS_BEGIN_OPERATION_CMD getKeyCharacteristics status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { errorCode = ErrorCode::UNKNOWN_ERROR; if(getTag(keyCharacteristics.hardwareEnforced, Tag::ALGORITHM, param)) { errorCode = sendData(Instruction::INS_BEGIN_OPERATION_CMD, cborData, cborOutData); - LOG(DEBUG) << "INS_BEGIN_OPERATION_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); - LOG(DEBUG) << "INS_BEGIN_OPERATION_CMD decodeData status: " << as_integer(errorCode); if (item != nullptr) { if(!cborConverter_.getKeyParameters(item, 1, outParams) || !cborConverter_.getUint64(item, 2, operationHandle)) { errorCode = ErrorCode::UNKNOWN_ERROR; outParams.setToExternal(nullptr, 0); operationHandle = 0; - LOG(ERROR) << "Error in INS_BEGIN_OPERATION_CMD status: " << as_integer(errorCode); } else { /* Store the operationInfo */ oprCtx_->setOperationInfo(operationHandle, purpose, param.f.algorithm, inParams); } - } else { - LOG(ERROR) << "Error in INS_BEGIN_OPERATION_CMD decodeData status: " << as_integer(errorCode); } - } else { - LOG(ERROR) << "Error in INS_BEGIN_OPERATION_CMD status: " << as_integer(errorCode); } - } else { - LOG(ERROR) << "INS_BEGIN_OPERATION_CMD couldn't find tag: " << as_integer(Tag::ALGORITHM); } - } else { - LOG(ERROR) << "INS_BEGIN_OPERATION_CMD error in getKeyCharacteristics status: " << as_integer(errorCode); } /* Create a new operation handle and add a entry inside the operation table map with * key - new operation handle @@ -1217,9 +1090,6 @@ Return JavacardKeymaster4Device::begin(KeyPurpose purpose, const hidl_vec< */ if (ErrorCode::OK == errorCode) errorCode = createOprHandleEntry(operationHandle, SB_KM_OPR, generatedOpHandle); - else - LOG(ERROR) << "Error in INS_BEGIN_OPERATION_CMD status: " << as_integer(errorCode); - _hidl_cb(errorCode, outParams, generatedOpHandle); return Void(); } @@ -1241,7 +1111,6 @@ Return JavacardKeymaster4Device::update(uint64_t halGeneratedOprHandle, co if (!isStrongboxOperation(halGeneratedOprHandle)) { /* SW keymaster (Public key operation) */ - LOG(DEBUG) << "INS_UPDATE_OPERATION_CMD - swkm operation "; UpdateOperationRequest request; request.op_handle = operationHandle; request.input.Reinitialize(input.data(), input.size()); @@ -1249,15 +1118,10 @@ Return JavacardKeymaster4Device::update(uint64_t halGeneratedOprHandle, co softKm_->UpdateOperation(request, &response); errorCode = legacy_enum_conversion(response.error); - LOG(DEBUG) << "INS_UPDATE_OPERATION_CMD - swkm update operation status: " - << as_integer(errorCode); if (response.error == KM_ERROR_OK) { inputConsumed = response.input_consumed; outParams = kmParamSet2Hidl(response.output_params); output = kmBuffer2hidlVec(response.output); - } else { - LOG(ERROR) << "INS_UPDATE_OPERATION_CMD - error swkm update operation status: " - << as_integer(errorCode); } } else { /* Strongbox Keymaster operation */ @@ -1277,13 +1141,10 @@ Return JavacardKeymaster4Device::update(uint64_t halGeneratedOprHandle, co //ASSOCIATED_DATA present in KeyParameters. Then we need to make a call to javacard Applet. if(data.size() == 0 && !findTag(inParams, Tag::ASSOCIATED_DATA)) { //Return OK, since this is not error case. - LOG(DEBUG) << "sendDataCallback: data size is zero"; return ErrorCode::OK; } if(ErrorCode::OK != (errorCode = encodeParametersVerified(verificationToken, asn1ParamsVerified))) { - LOG(ERROR) << "sendDataCallback: error in encodeParametersVerified status: " - << as_integer(errorCode); return errorCode; } @@ -1296,15 +1157,11 @@ Return JavacardKeymaster4Device::update(uint64_t halGeneratedOprHandle, co std::vector cborData = array.encode(); errorCode = sendData(Instruction::INS_UPDATE_OPERATION_CMD, cborData, cborOutData); - LOG(DEBUG) << "sendDataCallback: INS_UPDATE_OPERATION_CMD status: " - << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); - LOG(DEBUG) << "sendDataCallback: INS_UPDATE_OPERATION_CMD decodeData status: " - << as_integer(errorCode); if (item != nullptr) { /*Ignore inputConsumed from javacard SE since HAL consumes all the input */ //cborConverter_.getUint64(item, 1, inputConsumed); @@ -1317,16 +1174,8 @@ Return JavacardKeymaster4Device::update(uint64_t halGeneratedOprHandle, co outParams.setToExternal(nullptr, 0); tempOut.clear(); errorCode = ErrorCode::UNKNOWN_ERROR; - LOG(ERROR) << "sendDataCallback: error in INS_UPDATE_OPERATION_CMD status: " - << as_integer(errorCode); } - } else { - LOG(ERROR) << "sendDataCallback: INS_UPDATE_OPERATION_CMD error in decodeData status: " - << as_integer(errorCode); } - } else { - LOG(ERROR) << "sendDataCallback: error in INS_UPDATE_OPERATION_CMD status: " - << as_integer(errorCode); } return errorCode; }; @@ -1336,15 +1185,12 @@ Return JavacardKeymaster4Device::update(uint64_t halGeneratedOprHandle, co inputConsumed = input.size(); output = tempOut; } - LOG(DEBUG) << "Update operation status: " << as_integer(errorCode); if(ErrorCode::OK != errorCode) { - LOG(ERROR) << "Error in update operation, status: " << as_integer(errorCode); abort(halGeneratedOprHandle); } } if(ErrorCode::OK != errorCode) { /* Delete the entry from operation table. */ - LOG(ERROR) << "Delete entry from operation table, status: " << as_integer(errorCode); deleteOprHandleEntry(halGeneratedOprHandle); } @@ -1369,7 +1215,6 @@ Return JavacardKeymaster4Device::finish(uint64_t halGeneratedOprHandle, co if (!isStrongboxOperation(halGeneratedOprHandle)) { /* SW keymaster (Public key operation) */ - LOG(DEBUG) << "FINISH - swkm operation "; FinishOperationRequest request; request.op_handle = operationHandle; request.input.Reinitialize(input.data(), input.size()); @@ -1379,13 +1224,10 @@ Return JavacardKeymaster4Device::finish(uint64_t halGeneratedOprHandle, co softKm_->FinishOperation(request, &response); errorCode = legacy_enum_conversion(response.error); - LOG(DEBUG) << "FINISH - swkm operation, status: " << as_integer(errorCode); if (response.error == KM_ERROR_OK) { outParams = kmParamSet2Hidl(response.output_params); output = kmBuffer2hidlVec(response.output); - } else { - LOG(ERROR) << "Error in finish operation, status: " << as_integer(errorCode); } } else { /* Strongbox Keymaster operation */ @@ -1407,7 +1249,6 @@ Return JavacardKeymaster4Device::finish(uint64_t halGeneratedOprHandle, co std::vector asn1ParamsVerified; if(ErrorCode::OK != (errorCode = encodeParametersVerified(verificationToken, asn1ParamsVerified))) { - LOG(ERROR) << "sendDataCallback: Error in encodeParametersVerified, status: " << as_integer(errorCode); return errorCode; } @@ -1419,7 +1260,6 @@ Return JavacardKeymaster4Device::finish(uint64_t halGeneratedOprHandle, co array.add(operationHandle); if(finish) { std::vector finishParams; - LOG(DEBUG) << "sendDataCallback: finish operation"; if(aadTag) { for(int i = 0; i < inParams.size(); i++) { if(inParams[i].tag != Tag::ASSOCIATED_DATA) @@ -1435,7 +1275,6 @@ Return JavacardKeymaster4Device::finish(uint64_t halGeneratedOprHandle, co keyParamPos = 1; outputPos = 2; } else { - LOG(DEBUG) << "sendDataCallback: update operation"; if(findTag(inParams, Tag::ASSOCIATED_DATA)) { aadTag = true; } @@ -1449,13 +1288,11 @@ Return JavacardKeymaster4Device::finish(uint64_t halGeneratedOprHandle, co cborConverter_.addVerificationToken(array, verificationToken, asn1ParamsVerified); std::vector cborData = array.encode(); errorCode = sendData(ins, cborData, cborOutData); - LOG(DEBUG) << "sendDataCallback: operation: " << as_integer(ins) << " status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); - LOG(DEBUG) << "sendDataCallback: operation: " << as_integer(ins) << " decodeData status: " << as_integer(errorCode); if (item != nullptr) { //There is a change that this finish callback may gets called multiple times if the input data size //is larger the MAX_ALLOWED_INPUT_SIZE (Refer OperationContext) so parse and get the outParams only @@ -1467,13 +1304,8 @@ Return JavacardKeymaster4Device::finish(uint64_t halGeneratedOprHandle, co outParams.setToExternal(nullptr, 0); tempOut.clear(); errorCode = ErrorCode::UNKNOWN_ERROR; - LOG(ERROR) << "sendDataCallback: error in operation: " << as_integer(ins) << " decodeData, status: " << as_integer(errorCode); } - } else { - LOG(ERROR) << "sendDataCallback: error in operation: " << as_integer(ins) << " status: " << as_integer(errorCode); } - } else { - LOG(ERROR) << "sendDataCallback: error in operation: " << as_integer(ins) << " status: " << as_integer(errorCode); } return errorCode; }; @@ -1482,14 +1314,12 @@ Return JavacardKeymaster4Device::finish(uint64_t halGeneratedOprHandle, co output = tempOut; } if (ErrorCode::OK != errorCode) { - LOG(ERROR) << "Error in finish operation, status: " << as_integer(errorCode); abort(halGeneratedOprHandle); } } /* Delete the entry from operation table. */ deleteOprHandleEntry(halGeneratedOprHandle); oprCtx_->clearOperationData(operationHandle); - LOG(DEBUG) << "finish operation, status: " << as_integer(errorCode); _hidl_cb(errorCode, outParams, output); return Void(); } @@ -1509,7 +1339,6 @@ Return JavacardKeymaster4Device::abort(uint64_t halGeneratedOprHandle softKm_->AbortOperation(request, &response); errorCode = legacy_enum_conversion(response.error); - LOG(DEBUG) << "swkm abort operation, status: " << as_integer(errorCode); if (response.error == KM_ERROR_INVALID_OPERATION_HANDLE) { cppbor::Array array; std::unique_ptr item; @@ -1520,18 +1349,12 @@ Return JavacardKeymaster4Device::abort(uint64_t halGeneratedOprHandle std::vector cborData = array.encode(); errorCode = sendData(Instruction::INS_ABORT_OPERATION_CMD, cborData, cborOutData); - LOG(DEBUG) << "INS_ABORT_OPERATION_CMD status: " << as_integer(errorCode); if(errorCode == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData(cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); - LOG(DEBUG) << "INS_ABORT_OPERATION_CMD decodeData status: " << as_integer(errorCode); - } else { - LOG(ERROR) << "Error in INS_ABORT_OPERATION_CMD, status: " << as_integer(errorCode); } - } else { - LOG(DEBUG) << "Error in swkm abort operation, status: " << as_integer(errorCode); } /* Delete the entry on this operationHandle */ oprCtx_->clearOperationData(operationHandle); @@ -1549,7 +1372,6 @@ Return<::android::hardware::keymaster::V4_1::ErrorCode> JavacardKeymaster4Device ErrorCode ret = ErrorCode::UNKNOWN_ERROR; if(ErrorCode::OK != (ret = encodeParametersVerified(verificationToken, asn1ParamsVerified))) { - LOG(DEBUG) << "INS_DEVICE_LOCKED_CMD: Error in encodeParametersVerified, status: " << as_integer(errorCode); return errorCode; } @@ -1559,15 +1381,11 @@ Return<::android::hardware::keymaster::V4_1::ErrorCode> JavacardKeymaster4Device std::vector cborData = array.encode(); ret = sendData(Instruction::INS_DEVICE_LOCKED_CMD, cborData, cborOutData); - LOG(DEBUG) << "INS_DEVICE_LOCKED_CMD status: " << as_integer(ret); if(ret == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData<::android::hardware::keymaster::V4_1::ErrorCode>( cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); - LOG(DEBUG) << "INS_DEVICE_LOCKED_CMD decodeData status: " << as_integer(errorCode); - } else { - LOG(ERROR) << "Error in INS_DEVICE_LOCKED_CMD, status: " << as_integer(ret); } return errorCode; } @@ -1580,15 +1398,11 @@ Return<::android::hardware::keymaster::V4_1::ErrorCode> JavacardKeymaster4Device ::android::hardware::keymaster::V4_1::ErrorCode errorCode = ::android::hardware::keymaster::V4_1::ErrorCode::UNKNOWN_ERROR; ErrorCode ret = sendData(Instruction::INS_EARLY_BOOT_ENDED_CMD, cborInput, cborOutData); - LOG(DEBUG) << "INS_EARLY_BOOT_ENDED_CMD status: " << as_integer(ret); if(ret == ErrorCode::OK) { //Skip last 2 bytes in cborData, it contains status. std::tie(item, errorCode) = decodeData<::android::hardware::keymaster::V4_1::ErrorCode>( cborConverter_, std::vector(cborOutData.begin(), cborOutData.end()-2), true, oprCtx_); - LOG(DEBUG) << "INS_EARLY_BOOT_ENDED_CMD decodeData status: " << as_integer(errorCode); - } else { - LOG(ERROR) << "Error in INS_EARLY_BOOT_ENDED_CMD, status: " << as_integer(ret); } return errorCode; } From 8bf8705a0ee2ef3b3f3c0824877af08eaafc01ee Mon Sep 17 00:00:00 2001 From: "rajesh.nyamagoud" Date: Thu, 29 Jul 2021 11:47:25 -0700 Subject: [PATCH 3/3] Adding OMAPIService support to communicate with SE OMAPI vendor stable service transport APIs integrated to communicate with secure element. --- .../4.1/JavacardKeymaster4Device.cpp | 2 +- HAL/keymaster/4.1/OmapiTransport.cpp | 202 ++++++++++++++++-- HAL/keymaster/Android.bp | 9 +- HAL/keymaster/include/Transport.h | 24 +++ 4 files changed, 223 insertions(+), 14 deletions(-) diff --git a/HAL/keymaster/4.1/JavacardKeymaster4Device.cpp b/HAL/keymaster/4.1/JavacardKeymaster4Device.cpp index 87daddbc..20a1ac5c 100644 --- a/HAL/keymaster/4.1/JavacardKeymaster4Device.cpp +++ b/HAL/keymaster/4.1/JavacardKeymaster4Device.cpp @@ -136,7 +136,7 @@ static inline std::unique_ptr& getTransportFacto if (!isEmulator) { std::string fingerprint = android::base::GetProperty(PROP_BUILD_FINGERPRINT, ""); if (!fingerprint.empty()) { - if (fingerprint.find(CUTTLEFISH_FINGERPRINT_SS, 0)) { + if (fingerprint.find(CUTTLEFISH_FINGERPRINT_SS, 0) != std::string::npos) { isEmulator = true; } } diff --git a/HAL/keymaster/4.1/OmapiTransport.cpp b/HAL/keymaster/4.1/OmapiTransport.cpp index 5aaefc91..e7bd9a84 100644 --- a/HAL/keymaster/4.1/OmapiTransport.cpp +++ b/HAL/keymaster/4.1/OmapiTransport.cpp @@ -14,36 +14,214 @@ ** See the License for the specific language governing permissions and ** limitations under the License. */ -#include -#include -#include -#include -#include +#include +#include +#include +#include +#include #include + +#include + #include "Transport.h" -#define PORT 8080 -#define IPADDR "10.9.40.24" #define UNUSED_V(a) a=a namespace se_transport { -bool OmapiTransport::openConnection() { +class SEListener : public ::aidl::android::system::omapi::BnSecureElementListener {}; + +bool OmapiTransport::initialize() { + std::vector readers = {}; + + LOG(DEBUG) << "Initialize the secure element connection"; + + // Get OMAPI vendor stable service handler + ::ndk::SpAIBinder ks2Binder(AServiceManager_getService(omapiServiceName)); + omapiSeService = aidl::android::system::omapi::ISecureElementService::fromBinder(ks2Binder); + + if (omapiSeService == nullptr) { + LOG(ERROR) << "Failed to start omapiSeService null"; + return false; + } + + // reset readers, clear readers if already existing + if (mVSReaders.size() > 0) { + closeConnection(); + } + + // Get available readers + auto status = omapiSeService->getReaders(&readers); + if (!status.isOk()) { + LOG(ERROR) << "getReaders failed to get available readers: " << status.getMessage(); + return false; + } + + // Get SE readers handlers + for (auto readerName : readers) { + std::shared_ptr<::aidl::android::system::omapi::ISecureElementReader> reader; + status = omapiSeService->getReader(readerName, &reader); + if (!status.isOk()) { + LOG(ERROR) << "getReader for " << readerName.c_str() << " Failed: " + << status.getMessage(); + return false; + } + + mVSReaders[readerName] = reader; + } + + // Find eSE reader, as of now assumption is only eSE available on device + LOG(DEBUG) << "Finding eSE reader"; + eSEReader = nullptr; + if (mVSReaders.size() > 0) { + for (const auto& [name, reader] : mVSReaders) { + if (name.find(ESE_READER_PREFIX, 0) != std::string::npos) { + LOG(DEBUG) << "eSE reader found: " << name; + eSEReader = reader; + } + } + } + + if (eSEReader == nullptr) { + LOG(ERROR) << "secure element reader " << ESE_READER_PREFIX << " not found"; + return false; + } + return true; } -bool OmapiTransport::sendData(const uint8_t* inData, const size_t inLen, std::vector& output) { - std::vector test(inData, inData+inLen); - output = std::move(test); +bool OmapiTransport::internalTransmitApdu( + std::shared_ptr reader, + std::vector apdu, std::vector& transmitResponse) { + std::shared_ptr session; + std::shared_ptr channel; + auto mSEListener = std::make_shared(); + std::vector selectResponse = {}; + std::vector SELECTABLE_AID = {0xA0, 0x00, 0x00, 0x04, 0x76, 0x41, 0x6E, 0x64, + 0x72, 0x6F, 0x69, 0x64, 0x43, 0x54, 0x53, 0x31}; + + LOG(DEBUG) << "internalTransmitApdu: trasmitting data to secure element"; + + if (reader == nullptr) { + LOG(ERROR) << "eSE reader is null"; + return false; + } + + bool status = false; + auto res = reader->isSecureElementPresent(&status); + if (!res.isOk()) { + LOG(ERROR) << "isSecureElementPresent error: " << res.getMessage(); + return false; + } + if (!status) { + LOG(ERROR) << "secure element not found"; + return false; + } + + res = reader->openSession(&session); + if (!res.isOk()) { + LOG(ERROR) << "openSession error: " << res.getMessage(); + return false; + } + if (session == nullptr) { + LOG(ERROR) << "Could not open session null"; + return false; + } + + res = session->openLogicalChannel(SELECTABLE_AID, 0x00, mSEListener, &channel); + if (!res.isOk()) { + LOG(ERROR) << "openLogicalChannel error: " << res.getMessage(); + return false; + } + if (channel == nullptr) { + LOG(ERROR) << "Could not open channel null"; + return false; + } + + res = channel->getSelectResponse(&selectResponse); + if (!res.isOk()) { + LOG(ERROR) << "getSelectResponse error: " << res.getMessage(); + return false; + } + if (selectResponse.size() < 2) { + LOG(ERROR) << "getSelectResponse size error"; + return false; + } + + res = channel->transmit(apdu, &transmitResponse); + if (channel != nullptr) channel->close(); + if (session != nullptr) session->close(); + + LOG(INFO) << "STATUS OF TRNSMIT: " << res.getExceptionCode() << " Message: " + << res.getMessage(); + if (!res.isOk()) { + LOG(ERROR) << "transmit error: " << res.getMessage(); + return false; + } + return true; } +bool OmapiTransport::openConnection() { + + // if already conection setup done, no need to initialise it again. + if (isConnected()) { + return true; + } + + return initialize(); +} + +bool OmapiTransport::sendData(const uint8_t* inData, const size_t inLen, + std::vector& output) { + std::vector apdu(inData, inData+inLen); + + if (!isConnected()) { + // Try to initialize connection to eSE + LOG(INFO) << "Failed to send data, try to initialize connection SE connection"; + if (!initialize()) { + LOG(ERROR) << "Failed to send data, initialization not completed"; + closeConnection(); + return false; + } + } + + if (inData == NULL) { + LOG(ERROR) << "Failed to send data, APDU is null"; + return false; + } + + if (eSEReader != nullptr) { + LOG(DEBUG) << "Sending apdu data to secure element: " << ESE_READER_PREFIX; + return internalTransmitApdu(eSEReader, apdu, output); + } else { + LOG(ERROR) << "secure element reader " << ESE_READER_PREFIX << " not found"; + return false; + } +} + bool OmapiTransport::closeConnection() { + LOG(DEBUG) << "Closing all connections"; + if (omapiSeService != nullptr) { + if (mVSReaders.size() > 0) { + for (const auto& [name, reader] : mVSReaders) { + reader->closeSessions(); + } + mVSReaders.clear(); + } + } return true; } bool OmapiTransport::isConnected() { - return true; + // Check already initialization completed or not + if (omapiSeService != nullptr && eSEReader != nullptr) { + LOG(DEBUG) << "Connection initialization already completed"; + return true; + } + + LOG(DEBUG) << "Connection initialization not completed"; + return false; } } diff --git a/HAL/keymaster/Android.bp b/HAL/keymaster/Android.bp index cb88780c..6e30218e 100644 --- a/HAL/keymaster/Android.bp +++ b/HAL/keymaster/Android.bp @@ -47,6 +47,10 @@ cc_binary { "libjc_transport", "libjc_common", "libcrypto", + "libbinder_ndk", + ], + static_libs: [ + "android.system.omapi-V1-ndk_platform", ], required: [ "android.hardware.strongbox_keystore.xml", @@ -87,7 +91,6 @@ cc_library { cc_library { name: "libjc_transport", - host_supported: true, vendor_available: true, vndk: { enabled: true, @@ -104,6 +107,10 @@ cc_library { "libbinder", "libbase", "liblog", + "libbinder_ndk", + ], + static_libs: [ + "android.system.omapi-V1-ndk_platform", ], } diff --git a/HAL/keymaster/include/Transport.h b/HAL/keymaster/include/Transport.h index c6674dca..1df7bf4f 100644 --- a/HAL/keymaster/include/Transport.h +++ b/HAL/keymaster/include/Transport.h @@ -17,6 +17,17 @@ #ifndef __SE_TRANSPORT__ #define __SE_TRANSPORT__ +#include +#include +#include +#include +#include +#include +#include +#include + +#include + namespace se_transport { /** @@ -75,6 +86,19 @@ class OmapiTransport : public ITransport { */ bool isConnected() override; +private: + std::shared_ptr omapiSeService = nullptr; + std::shared_ptr eSEReader = nullptr; + std::map> + mVSReaders = {}; + std::string const ESE_READER_PREFIX = "eSE"; + constexpr static const char omapiServiceName[] = + "android.system.omapi.ISecureElementService/default"; + + bool initialize(); + bool internalTransmitApdu( + std::shared_ptr reader, + std::vector apdu, std::vector& transmitResponse); }; class SocketTransport : public ITransport {