From 1c0ef565f81ff655cbaecadc6c496c8b899b8162 Mon Sep 17 00:00:00 2001 From: Rajesh Nyamagoud Date: Tue, 4 May 2021 09:09:45 -0700 Subject: [PATCH 1/4] 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/4] 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 2b6aa26b1fb6480b694179a28cbe93b3109225d1 Mon Sep 17 00:00:00 2001 From: Rajesh Nyamagoud Date: Sat, 14 Aug 2021 00:15:20 +0000 Subject: [PATCH 3/4] Support for command chaining and response chaining Short length APDU with command chaining and response chaining are supported. --- .../javacard/keymaster/KMKeymasterApplet.java | 140 +++++++++++++++++- 1 file changed, 133 insertions(+), 7 deletions(-) diff --git a/Applet/src/com/android/javacard/keymaster/KMKeymasterApplet.java b/Applet/src/com/android/javacard/keymaster/KMKeymasterApplet.java index 0949177f..0fbd562d 100644 --- a/Applet/src/com/android/javacard/keymaster/KMKeymasterApplet.java +++ b/Applet/src/com/android/javacard/keymaster/KMKeymasterApplet.java @@ -39,6 +39,7 @@ public class KMKeymasterApplet extends Applet implements AppletEvent, ExtendedLe public static final short MAX_LENGTH = (short) 0x2000; private static final byte CLA_ISO7816_NO_SM_NO_CHAN = (byte) 0x80; private static final short KM_HAL_VERSION = (short) 0x4000; + private static final short KM_HAL_CHAIN_VERSION = (short) 0x4080; private static final short MAX_AUTH_DATA_SIZE = (short) 512; private static final short DERIVE_KEY_INPUT_SIZE = (short) 256; private static final short POWER_RESET_MASK_FLAG = (short) 0x4000; @@ -115,6 +116,10 @@ public class KMKeymasterApplet extends Applet implements AppletEvent, ExtendedLe private static final byte INS_END_KM_CMD = 0x7F; + private static final byte INS_GET_RESPONSE_CMD = (byte)0xC0; + private static final short SHORT_APDU_DATA_LEN = 255; + private static final short SHORT_RESPONSE_DATA_LEN = 256; + // Provision reporting status private static final byte NOT_PROVISIONED = 0x00; private static final byte PROVISION_STATUS_ATTESTATION_KEY = 0x01; @@ -190,6 +195,9 @@ public class KMKeymasterApplet extends Applet implements AppletEvent, ExtendedLe protected static short[] data; protected static byte provisionStatus = NOT_PROVISIONED; + protected static boolean responseChainingEnabled = false; + protected static boolean cmdChainingEnabled = false; + /** * Registers this applet. */ @@ -298,7 +306,8 @@ protected void validateApduHeader(APDU apdu) { } // Validate P1P2. - if (P1P2 != KMKeymasterApplet.KM_HAL_VERSION) { + if (P1P2 != KMKeymasterApplet.KM_HAL_VERSION + && P1P2 != KMKeymasterApplet.KM_HAL_CHAIN_VERSION) { ISOException.throwIt(ISO7816.SW_INCORRECT_P1P2); } } @@ -336,7 +345,8 @@ public void process(APDU apdu) { byte apduIns = apduBuffer[ISO7816.OFFSET_INS]; // Validate whether INS can be supported - if (!(apduIns > INS_BEGIN_KM_CMD && apduIns < INS_END_KM_CMD)) { + if (!(apduIns > INS_BEGIN_KM_CMD && apduIns < INS_END_KM_CMD) + && (apduIns != INS_GET_RESPONSE_CMD)) { ISOException.throwIt(ISO7816.SW_INS_NOT_SUPPORTED); } bufferRef[0] = repository.getHeap(); @@ -410,6 +420,9 @@ public void process(APDU apdu) { || ((keymasterState == KMKeymasterApplet.IN_PROVISION_STATE) && isProvisioningComplete())) { switch (apduIns) { + case INS_GET_RESPONSE_CMD: + processGetResponseCmd(apdu); + break; case INS_GENERATE_KEY_CMD: processGenerateKey(apdu); break; @@ -490,6 +503,11 @@ && isProvisioningComplete())) { sendError(apdu, KMException.getReason()); exception.clear(); } catch (ISOException exp) { + if (exp.getReason() == ISO7816.SW_BYTES_REMAINING_00) { + ISOException.throwIt(ISO7816.SW_BYTES_REMAINING_00); + } else if (exp.getReason() == ISO7816.SW_LAST_COMMAND_EXPECTED) { + return; + } sendError(apdu, mapISOErrorToKMError(exp.getReason())); freeOperations(); } catch (CryptoException e) { @@ -499,8 +517,11 @@ && isProvisioningComplete())) { freeOperations(); sendError(apdu, KMError.GENERIC_UNKNOWN_ERROR); } finally { - resetData(); - repository.clean(); + if (!responseChainingEnabled && !cmdChainingEnabled) { + resetData(); + repository.clean(); + + } } } @@ -585,8 +606,99 @@ public static void sendOutgoing(APDU apdu) { } // Send data apdu.setOutgoing(); - apdu.setOutgoingLength(bufferProp[BUF_LEN_OFFSET]); - apdu.sendBytesLong((byte[]) bufferRef[0], bufferProp[BUF_START_OFFSET], bufferProp[BUF_LEN_OFFSET]); + + if (bufferProp[BUF_LEN_OFFSET] > SHORT_RESPONSE_DATA_LEN) { + // If response data length is more than 256 then split the response + // in to multiple chunk of responses of each 256 bytes length + apdu.setOutgoingLength(SHORT_RESPONSE_DATA_LEN); + apdu.sendBytesLong((byte[]) bufferRef[0], bufferProp[BUF_START_OFFSET], + SHORT_RESPONSE_DATA_LEN); + + // Update response data offset and remaining length to be sent + bufferProp[BUF_START_OFFSET] = (short)(bufferProp[BUF_START_OFFSET] + + SHORT_RESPONSE_DATA_LEN); + bufferProp[BUF_LEN_OFFSET] = (short)(bufferProp[BUF_LEN_OFFSET] - SHORT_RESPONSE_DATA_LEN); + + // Enable response chaining to send remaining response data + responseChainingEnabled = true; + + // Throw an exception to indicate more response data exist for this command (sw1sw2=0x6100) + ISOException.throwIt(ISO7816.SW_BYTES_REMAINING_00); + } else { + // send last part of command response or the only chunk of response data + apdu.setOutgoingLength(bufferProp[BUF_LEN_OFFSET]); + apdu.sendBytesLong((byte[]) bufferRef[0], bufferProp[BUF_START_OFFSET], + bufferProp[BUF_LEN_OFFSET]); + responseChainingEnabled = false; + } + } + + /** + * Handles Command chaining, if 8th bit of P2 is set then it indicates command chaining. + * This method keeps track of total length of command data and first chunk offset + * After receiving last part of the command chain it prepares final data to be processed. + * @param apdu + * @param startOffset + * @param lengthTillNow + */ + public static void handleCommandChaining(APDU apdu, short startOffset, short lengthTillNow) { + byte[] srcBuffer = apdu.getBuffer(); + // 8th bit of P2 will be set for command chaining. + short P1P2 = Util.getShort(srcBuffer, ISO7816.OFFSET_P1); + boolean cmdChainingApdu = (P1P2 == KMKeymasterApplet.KM_HAL_CHAIN_VERSION); + + // If already command chaining started + if (cmdChainingEnabled) { + // If this APDU is not marked with command chaining bit in P2 + // then it will be last part of the command, so prepare the final command data + // from chunks of data received in this command chain. + if (!cmdChainingApdu) { + // this will be the last APDU of this cmd chain + // Rearrange the command data received + short lastChunkOffset = bufferProp[BUF_START_OFFSET]; + short lastChunkLen = bufferProp[BUF_LEN_OFFSET]; + + // Copy all chunks of data in order in contiguous bytes of memory. + // chucks of command data are stored on heap and heap grows backwards. + // reordering of these chunks is required to make it contiguous bytes of data to process. + // Allocate for total command-data to be used by the command + short totalLength = (short) (lengthTillNow + bufferProp[BUF_LEN_OFFSET]); + bufferProp[BUF_START_OFFSET] = repository.allocReclaimableMemory(totalLength); + bufferProp[BUF_LEN_OFFSET] = totalLength; + + // Copy chunk by chunk in the received order to contiguous allocated memory + short index = bufferProp[BUF_START_OFFSET]; + short length = SHORT_APDU_DATA_LEN; + while (startOffset > lastChunkOffset) { + Util.arrayCopyNonAtomic((byte[]) bufferRef[0], startOffset, (byte[]) bufferRef[0], + index, length); + index += length; + startOffset -= length; + } + // Handle last chunk of data which can be less than SHORT_APDU_DATA_LEN bytes. + if ((short) (index - bufferProp[BUF_START_OFFSET]) < bufferProp[BUF_LEN_OFFSET]) { + Util.arrayCopyNonAtomic((byte[]) bufferRef[0], lastChunkOffset, (byte[]) bufferRef[0], + index, lastChunkLen); + } + } else { + // This apdu is not the last part of this command chain, + // store first chunk offset and total length of bytes received till now + bufferProp[BUF_LEN_OFFSET] = (short) (lengthTillNow + bufferProp[BUF_LEN_OFFSET]); + bufferProp[BUF_START_OFFSET] = startOffset; + } + } + + // Enable command chaining, if 8th bit of P2 is set + if (cmdChainingApdu) { + // if this command APDU is marked with command chaining (P1P2=0x4080), + // then enable to collect data from subsequent commands in this chain + cmdChainingEnabled = true; + + // Throw an exception to indicate next chunk of command data is required. + ISOException.throwIt(ISO7816.SW_LAST_COMMAND_EXPECTED); + } else { + cmdChainingEnabled = false; + } } /** @@ -596,15 +708,25 @@ public static void receiveIncoming(APDU apdu) { byte[] srcBuffer = apdu.getBuffer(); short recvLen = apdu.setIncomingAndReceive(); short srcOffset = apdu.getOffsetCdata(); + + // For command chaining use case to track total length of data received and + // its first chunk offset + short lengthTillNow = bufferProp[BUF_LEN_OFFSET]; + short startOffset = bufferProp[BUF_START_OFFSET]; + + // Get chunk of data from current APDU and allocate for it. bufferProp[BUF_LEN_OFFSET] = apdu.getIncomingLength(); bufferProp[BUF_START_OFFSET] = repository.allocReclaimableMemory(bufferProp[BUF_LEN_OFFSET]); - short index = bufferProp[BUF_START_OFFSET]; + // Receive the chunk of command data from current APDU on to allocated memory. + short index = bufferProp[BUF_START_OFFSET]; while (recvLen > 0 && ((short) (index - bufferProp[BUF_START_OFFSET]) < bufferProp[BUF_LEN_OFFSET])) { Util.arrayCopyNonAtomic(srcBuffer, srcOffset, (byte[]) bufferRef[0], index, recvLen); index += recvLen; recvLen = apdu.receiveBytes(srcOffset); } + + handleCommandChaining(apdu, startOffset, lengthTillNow); } private void processGetHwInfoCmd(APDU apdu) { @@ -3302,6 +3424,10 @@ private void processSetBootParamsCmd(APDU apdu) { repository.initHmacNonce(scratchPad, (short) 0, KMRepository.HMAC_SEED_NONCE_SIZE); } + private static void processGetResponseCmd(APDU apdu) { + sendOutgoing(apdu); + } + private static void processGenerateKey(APDU apdu) { // Receive the incoming request fully from the master into buffer. receiveIncoming(apdu); From c58eb87425a958aadb3a074e0427c6424f80fa28 Mon Sep 17 00:00:00 2001 From: Rajesh Nyamagoud Date: Wed, 18 Aug 2021 16:24:45 +0000 Subject: [PATCH 4/4] [HAL] changes to support APDU chaining Changes made in HAL to support command chaining and response chaining. SocketTransport updated to handle response chaining. With this change HAL always sends short length APDUs to Applet --- .../4.1/JavacardKeymaster4Device.cpp | 99 ++++++++++++++++++- HAL/keymaster/4.1/SocketTransport.cpp | 68 ++++++++++++- HAL/keymaster/include/Transport.h | 3 + 3 files changed, 168 insertions(+), 2 deletions(-) diff --git a/HAL/keymaster/4.1/JavacardKeymaster4Device.cpp b/HAL/keymaster/4.1/JavacardKeymaster4Device.cpp index 87daddbc..0eae0b6c 100644 --- a/HAL/keymaster/4.1/JavacardKeymaster4Device.cpp +++ b/HAL/keymaster/4.1/JavacardKeymaster4Device.cpp @@ -21,6 +21,11 @@ #include #include #include + +#include +#include +#include + #include #include #include @@ -45,6 +50,11 @@ // Cuttlefish build fingerprint substring. #define CUTTLEFISH_FINGERPRINT_SS "aosp_cf_" +#define CMD_CHAINING_APDU_CLS 0x80 +#define CMD_CHAINING_APDU_P1 0x40 +#define CMD_CHAINING_APDU_P2 0x80 +#define APDU_SHORT_LENGTH 255 + #define APDU_CLS 0x80 #define APDU_P1 0x40 #define APDU_P2 0x00 @@ -136,7 +146,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; } } @@ -403,6 +413,57 @@ keyFormat, std::vector& wrappedKeyDescription) { return ErrorCode::OK; } +/** + * Construct the command chaining for extended length (command data > APDU_SHORT_LENGTH) APDU + */ +ErrorCode constructAPDUCmdChain(Instruction& ins, std::vector& inputData, + std::vector>& apduChain) { + if(inputData.size() >= USHRT_MAX) { + return (ErrorCode::INSUFFICIENT_BUFFER_SPACE); + } + + uint8_t* cmdData = inputData.data(); + size_t cmdDataLen = inputData.size(); + size_t index = 0; + + // Construct command chaining only if command data is of large length > APDU_SHORT_LENGTH + // otherwise signle short format APDU is created. + while((cmdDataLen - index) > APDU_SHORT_LENGTH) { + std::vector apduOut; + apduOut.push_back(static_cast(CMD_CHAINING_APDU_CLS)); //CLS + apduOut.push_back(static_cast(ins)); //INS + apduOut.push_back(static_cast(CMD_CHAINING_APDU_P1)); //P1 + apduOut.push_back(static_cast(CMD_CHAINING_APDU_P2)); //P2 + + apduOut.push_back(static_cast(0xFF)); //Lc + + std::vector data((cmdData + index), (cmdData + index + APDU_SHORT_LENGTH)); + apduOut.insert(apduOut.end(), std::begin(data), std::end(data)); + + apduChain.push_back(apduOut); + + index += APDU_SHORT_LENGTH; + } + + // Construct last APDU or the only APDU of the command + std::vector apduOut; + apduOut.push_back(static_cast(APDU_CLS)); //CLS + apduOut.push_back(static_cast(ins)); //INS + apduOut.push_back(static_cast(APDU_P1)); //P1 + apduOut.push_back(static_cast(APDU_P2)); //P2 + + if ((cmdDataLen - index) > 0) { + //apduOut.push_back(static_cast(0x00)); //Lc + apduOut.push_back(static_cast((cmdDataLen - index) & 0xFF)); + std::vector data((cmdData + index), (cmdData + cmdDataLen)); + apduOut.insert(apduOut.end(), std::begin(data), std::end(data)); + } + apduOut.push_back(static_cast(0x00)); //Le + + apduChain.push_back(apduOut); + return (ErrorCode::OK);//success +} + ErrorCode constructApduMessage(Instruction& ins, std::vector& inputData, std::vector& apduOut) { apduOut.push_back(static_cast(APDU_CLS)); //CLS apduOut.push_back(static_cast(ins)); //INS @@ -437,6 +498,8 @@ uint16_t getStatus(std::vector& inputData) { return (inputData.at(inputData.size()-2) << 8) | (inputData.at(inputData.size()-1)); } +/* +//TODO this method is kept just for reference to support extended length format ErrorCode sendData(Instruction ins, std::vector& inData, std::vector& response) { ErrorCode ret = ErrorCode::UNKNOWN_ERROR; std::vector apdu; @@ -460,6 +523,40 @@ ErrorCode sendData(Instruction ins, std::vector& inData, std::vector& inData, std::vector& response) { + ErrorCode ret = ErrorCode::UNKNOWN_ERROR; + std::vector> apduChain; + + // Constructs short length format APDUs based on the size of command data + ret = constructAPDUCmdChain(ins, inData, apduChain); + if(ret != ErrorCode::OK) { + LOG(ERROR) << "error in constructApduMessage cmd: " << (int32_t)ins << " status: " << (int32_t)ret; + return ret; + } + + // Send all APDUs in the command chain and get its response. + auto it = apduChain.begin(); + while (it != apduChain.end()) { + std::vector apdu = *it; + response.clear(); + + if(!getTransportFactoryInstance()->sendData(apdu.data(), apdu.size(), response)) { + LOG(ERROR) << "error in sendData cmd: " << (int32_t)ins << " status: " + << (int32_t)ErrorCode::SECURE_HW_COMMUNICATION_FAILED; + return (ErrorCode::SECURE_HW_COMMUNICATION_FAILED); + } + + // Response size should be greater than 2. Cbor output data followed by two bytes of APDU status. + if((response.size() < 2) || (getStatus(response) != APDU_RESP_STATUS_OK)) { + LOG(ERROR) << "error in sendData cmd: " << (int32_t)ins << " status: " << getStatus(response); + return (ErrorCode::UNKNOWN_ERROR); + } + ++it; + } + LOG(DEBUG) << "sendData cmd: " << (int32_t)ins << " status: " << (int32_t)ErrorCode::OK; + return (ErrorCode::OK);//success } /** diff --git a/HAL/keymaster/4.1/SocketTransport.cpp b/HAL/keymaster/4.1/SocketTransport.cpp index e060262f..c9cb7306 100644 --- a/HAL/keymaster/4.1/SocketTransport.cpp +++ b/HAL/keymaster/4.1/SocketTransport.cpp @@ -62,6 +62,66 @@ bool SocketTransport::openConnection() { return true; } +std::vector SocketTransport::getGetResponseCmdApdu() { + std::vector apduOut; + apduOut.push_back(static_cast(0x80)); //CLS + apduOut.push_back(static_cast(0xC0)); //INS + apduOut.push_back(static_cast(0x40)); //P1 + apduOut.push_back(static_cast(0x00)); //P2 + apduOut.push_back(static_cast(0x00)); + + return apduOut; +} + +bool SocketTransport::handleChainGetResponse(std::vector& output) { + if (output.size() < 2) { + return false; + } + + uint16_t apduStatus = (output.at(output.size()-2) << 8) | (output.at(output.size()-1)); + if (apduStatus != 0x6100) { + return false; + } + + uint8_t buffer[MAX_RECV_BUFFER_SIZE]; + + // Holds complete reponse data, as and when new data is received, it get + // appended to this container + std::vector responseChain; + + std::vector getResponseApdu = getGetResponseCmdApdu(); + + // more response data is pending to receive + while (apduStatus == 0x6100) { + responseChain.insert(std::end(responseChain), std::begin(output), std::end(output)-2); + + if (send(mSocket, getResponseApdu.data(), getResponseApdu.size() , MSG_NOSIGNAL)< 0) { + LOG(ERROR) << "Failed to send data over socket err: " << errno; + return false; + } + + size_t valRead = read( mSocket , buffer, MAX_RECV_BUFFER_SIZE); + if(0 > valRead) { + LOG(ERROR) << "Failed to read data from socket - getResponse."; + } + output.clear(); + for(size_t i = 0; i < valRead; i++) { + output.push_back(buffer[i]); + } + + apduStatus = (output.at(output.size()-2) << 8) | (output.at(output.size()-1)); + // Last response chunk + if (apduStatus != 0x6100) { + responseChain.insert(std::end(responseChain), std::begin(output), std::end(output)); + output.clear(); + // Set the output with total data received till now for this command. + output.insert(std::end(output), std::begin(responseChain), std::end(responseChain)); + return true; + } + } + return false; +} + bool SocketTransport::sendData(const uint8_t* inData, const size_t inLen, std::vector& output) { uint8_t buffer[MAX_RECV_BUFFER_SIZE]; int count = 1; @@ -78,7 +138,7 @@ bool SocketTransport::sendData(const uint8_t* inData, const size_t inLen, std::v return false; } - if (send(mSocket, inData, inLen , 0)< 0) { + if (send(mSocket, inData, inLen , MSG_NOSIGNAL)< 0) { static int connectionResetCnt = 0; /* To avoid loop */ if (ECONNRESET == errno && connectionResetCnt == 0) { //Connection reset. Try open socket and then sendData. @@ -98,6 +158,12 @@ bool SocketTransport::sendData(const uint8_t* inData, const size_t inLen, std::v for(size_t i = 0; i < valRead; i++) { output.push_back(buffer[i]); } + + uint16_t apduStatus = (output.at(output.size()-2) << 8) | (output.at(output.size()-1)); + if (apduStatus == 0x6100) { + return handleChainGetResponse(output); + } + return true; } diff --git a/HAL/keymaster/include/Transport.h b/HAL/keymaster/include/Transport.h index c6674dca..e43844ae 100644 --- a/HAL/keymaster/include/Transport.h +++ b/HAL/keymaster/include/Transport.h @@ -101,6 +101,9 @@ class SocketTransport : public ITransport { */ bool isConnected() override; private: + + std::vector getGetResponseCmdApdu(); + bool handleChainGetResponse(std::vector& output); /** * Socket instance. */