Widevine Metrics System

This change is the complete Widevine metrics system. It will
measure and record runtime information about what is happening
in the CDM - such as errors and throughput.

Bug: 33745339
Bug: 26027857
Change-Id: Ic9a82074f1e2b72c72d751b235f8ae361232787d
This commit is contained in:
Aaron Vaage
2017-01-17 18:31:25 -08:00
parent ee5aff7706
commit edb9f00df7
39 changed files with 2969 additions and 258 deletions

View File

@@ -14,6 +14,7 @@
#include "file_store.h"
#include "license_protocol.pb.h"
#include "log.h"
#include "metrics_front_end.h"
#include "properties.h"
#include "string_conversions.h"
#include "wv_cdm_constants.h"
@@ -73,6 +74,8 @@ CdmEngine::CdmEngine(FileSystem* file_system, const std::string& spoid)
srand(clock_.GetCurrentTime());
seeded_ = true;
}
life_span_.Start();
}
CdmEngine::~CdmEngine() {
@@ -82,6 +85,8 @@ CdmEngine::~CdmEngine() {
delete i->second;
}
sessions_.clear();
M_RECORD(&metrics_, cdm_engine_life_span_, life_span_.AsMs());
}
CdmResponseType CdmEngine::OpenSession(const CdmKeySystem& key_system,
@@ -278,7 +283,13 @@ CdmResponseType CdmEngine::GenerateKeyRequest(
if (license_type == kLicenseTypeRelease &&
!iter->second->license_received()) {
sts = iter->second->RestoreOfflineSession(key_set_id, kLicenseTypeRelease);
M_TIME(
sts = iter->second->RestoreOfflineSession(
key_set_id,
kLicenseTypeRelease),
iter->second->GetMetrics(),
cdm_session_restore_offline_session_,
sts);
if (sts != KEY_ADDED) {
LOGE("CdmEngine::GenerateKeyRequest: key release restoration failed,"
"sts = %d", static_cast<int>(sts));
@@ -286,13 +297,24 @@ CdmResponseType CdmEngine::GenerateKeyRequest(
}
}
sts = iter->second->GenerateKeyRequest(
init_data, license_type, app_parameters, key_request);
M_TIME(
sts = iter->second->GenerateKeyRequest(
init_data,
license_type,
app_parameters,
key_request),
iter->second->GetMetrics(),
cdm_session_generate_key_request_,
sts);
if (KEY_MESSAGE != sts) {
if (sts == NEED_PROVISIONING) {
cert_provisioning_requested_security_level_ =
iter->second->GetRequestedSecurityLevel();
M_TIME(
cert_provisioning_requested_security_level_ =
iter->second->GetRequestedSecurityLevel(),
iter->second->GetMetrics(),
cdm_session_get_requested_security_level_,
cert_provisioning_requested_security_level_);
}
LOGE("CdmEngine::GenerateKeyRequest: key request generation failed, "
"sts = %d", static_cast<int>(sts));
@@ -347,7 +369,13 @@ CdmResponseType CdmEngine::AddKey(const CdmSessionId& session_id,
return EMPTY_KEY_DATA_1;
}
CdmResponseType sts = iter->second->AddKey(key_data);
CdmResponseType sts;
M_TIME(
sts = iter->second->AddKey(
key_data),
iter->second->GetMetrics(),
cdm_session_add_key_,
sts);
if (key_set_id) {
*key_set_id = iter->second->key_set_id();
}
@@ -382,11 +410,21 @@ CdmResponseType CdmEngine::RestoreKey(const CdmSessionId& session_id,
return SESSION_NOT_FOUND_4;
}
CdmResponseType sts =
iter->second->RestoreOfflineSession(key_set_id, kLicenseTypeOffline);
CdmResponseType sts;
M_TIME(
sts = iter->second->RestoreOfflineSession(
key_set_id,
kLicenseTypeOffline),
iter->second->GetMetrics(),
cdm_session_restore_offline_session_,
sts);
if (sts == NEED_PROVISIONING) {
cert_provisioning_requested_security_level_ =
iter->second->GetRequestedSecurityLevel();
M_TIME(
cert_provisioning_requested_security_level_ =
iter->second->GetRequestedSecurityLevel(),
iter->second->GetMetrics(),
cdm_session_get_requested_security_level_,
cert_provisioning_requested_security_level_);
}
if (sts != KEY_ADDED && sts != GET_RELEASED_LICENSE_ERROR) {
LOGE("CdmEngine::RestoreKey: restore offline session failed = %d", sts);
@@ -404,7 +442,11 @@ CdmResponseType CdmEngine::RemoveKeys(const CdmSessionId& session_id) {
return SESSION_NOT_FOUND_5;
}
iter->second->ReleaseCrypto();
M_TIME(
iter->second->ReleaseCrypto(),
iter->second->GetMetrics(),
cdm_session_release_crypto_);
return NO_ERROR;
}
@@ -426,7 +468,13 @@ CdmResponseType CdmEngine::GenerateRenewalRequest(
key_request->message.clear();
CdmResponseType sts = iter->second->GenerateRenewalRequest(key_request);
CdmResponseType sts;
M_TIME(
sts= iter->second->GenerateRenewalRequest(
key_request),
iter->second->GetMetrics(),
cdm_session_generate_renewal_request_,
sts);
if (KEY_MESSAGE != sts) {
LOGE("CdmEngine::GenerateRenewalRequest: key request gen. failed, sts=%d",
@@ -452,7 +500,13 @@ CdmResponseType CdmEngine::RenewKey(const CdmSessionId& session_id,
return EMPTY_KEY_DATA_2;
}
CdmResponseType sts = iter->second->RenewKey(key_data);
CdmResponseType sts;
M_TIME(
sts = iter->second->RenewKey(
key_data),
iter->second->GetMetrics(),
cdm_session_renew_key_,
sts);
if (KEY_ADDED != sts) {
LOGE("CdmEngine::RenewKey: keys not added, sts=%d", static_cast<int>(sts));
return sts;
@@ -465,9 +519,16 @@ CdmResponseType CdmEngine::QueryStatus(SecurityLevel security_level,
const std::string& query_token,
std::string* query_response) {
LOGI("CdmEngine::QueryStatus");
CryptoSession crypto_session;
CryptoSession crypto_session(&metrics_);
if (security_level == kLevel3) {
CdmResponseType status = crypto_session.Open(kLevel3);
CdmResponseType status;
M_TIME(
status = crypto_session.Open(
kLevel3),
&metrics_,
crypto_session_open_,
status,
kLevel3);
if (NO_ERROR != status) return INVALID_QUERY_STATUS;
}
@@ -477,7 +538,12 @@ CdmResponseType CdmEngine::QueryStatus(SecurityLevel security_level,
}
if (query_token == QUERY_KEY_SECURITY_LEVEL) {
CdmSecurityLevel security_level = crypto_session.GetSecurityLevel();
CdmSecurityLevel security_level;
M_TIME(
security_level = crypto_session.GetSecurityLevel(),
&metrics_,
crypto_session_get_security_level_,
security_level);
switch (security_level) {
case kSecurityLevelL1:
*query_response = QUERY_VALUE_SECURITY_LEVEL_L1;
@@ -499,7 +565,14 @@ CdmResponseType CdmEngine::QueryStatus(SecurityLevel security_level,
}
} else if (query_token == QUERY_KEY_DEVICE_ID) {
std::string deviceId;
if (!crypto_session.GetDeviceUniqueId(&deviceId)) {
bool got_id;
M_TIME(
got_id = crypto_session.GetDeviceUniqueId(
&deviceId),
&metrics_,
crypto_session_get_device_unique_id_,
got_id);
if (!got_id) {
LOGW("CdmEngine::QueryStatus: QUERY_KEY_DEVICE_ID unknown failure");
return UNKNOWN_ERROR;
}
@@ -507,7 +580,15 @@ CdmResponseType CdmEngine::QueryStatus(SecurityLevel security_level,
*query_response = deviceId;
} else if (query_token == QUERY_KEY_SYSTEM_ID) {
uint32_t system_id;
if (!crypto_session.GetSystemId(&system_id)) {
bool got_id;
M_TIME(
got_id = crypto_session.GetSystemId(
&system_id),
&metrics_,
crypto_session_get_system_id_,
got_id,
system_id);
if (!got_id) {
LOGW("CdmEngine::QueryStatus: QUERY_KEY_SYSTEM_ID unknown failure");
return UNKNOWN_ERROR;
}
@@ -517,7 +598,14 @@ CdmResponseType CdmEngine::QueryStatus(SecurityLevel security_level,
*query_response = system_id_stream.str();
} else if (query_token == QUERY_KEY_PROVISIONING_ID) {
std::string provisioning_id;
if (!crypto_session.GetProvisioningId(&provisioning_id)) {
bool got_id;
M_TIME(
got_id = crypto_session.GetProvisioningId(
&provisioning_id),
&metrics_,
crypto_session_get_provisioning_id_,
got_id);
if (!got_id) {
LOGW("CdmEngine::QueryStatus: GetProvisioningId failed");
return UNKNOWN_ERROR;
}
@@ -527,7 +615,15 @@ CdmResponseType CdmEngine::QueryStatus(SecurityLevel security_level,
query_token == QUERY_KEY_MAX_HDCP_LEVEL) {
CryptoSession::HdcpCapability current_hdcp;
CryptoSession::HdcpCapability max_hdcp;
if (!crypto_session.GetHdcpCapabilities(&current_hdcp, &max_hdcp)) {
bool got_hdcp;
M_TIME(
got_hdcp = crypto_session.GetHdcpCapabilities(
&current_hdcp,
&max_hdcp),
&metrics_,
crypto_session_get_hdcp_capabilities_,
got_hdcp);
if (!got_hdcp) {
LOGW("CdmEngine::QueryStatus: GetHdcpCapabilities failed");
return UNKNOWN_ERROR;
}
@@ -536,7 +632,14 @@ CdmResponseType CdmEngine::QueryStatus(SecurityLevel security_level,
current_hdcp : max_hdcp);
} else if (query_token == QUERY_KEY_USAGE_SUPPORT) {
bool supports_usage_reporting;
if (!crypto_session.UsageInformationSupport(&supports_usage_reporting)) {
bool got_info;
M_TIME(
got_info = crypto_session.UsageInformationSupport(
&supports_usage_reporting),
&metrics_,
crypto_session_usage_information_support_,
got_info);
if (!got_info) {
LOGW("CdmEngine::QueryStatus: UsageInformationSupport failed");
return UNKNOWN_ERROR;
}
@@ -545,7 +648,14 @@ CdmResponseType CdmEngine::QueryStatus(SecurityLevel security_level,
supports_usage_reporting ? QUERY_VALUE_TRUE : QUERY_VALUE_FALSE;
} else if (query_token == QUERY_KEY_NUMBER_OF_OPEN_SESSIONS) {
size_t number_of_open_sessions;
if (!crypto_session.GetNumberOfOpenSessions(&number_of_open_sessions)) {
bool got_num;
M_TIME(
got_num = crypto_session.GetNumberOfOpenSessions(
&number_of_open_sessions),
&metrics_,
crypto_session_get_number_of_open_sessions_,
got_num);
if (!got_num) {
LOGW("CdmEngine::QueryStatus: GetNumberOfOpenSessions failed");
return UNKNOWN_ERROR;
}
@@ -555,7 +665,14 @@ CdmResponseType CdmEngine::QueryStatus(SecurityLevel security_level,
*query_response = open_sessions_stream.str();
} else if (query_token == QUERY_KEY_MAX_NUMBER_OF_SESSIONS) {
size_t maximum_number_of_sessions;
if (!crypto_session.GetMaxNumberOfSessions(&maximum_number_of_sessions)) {
bool got_num;
M_TIME(
got_num = crypto_session.GetMaxNumberOfSessions(
&maximum_number_of_sessions),
&metrics_,
crypto_session_get_max_number_of_sessions_,
got_num);
if (!got_num) {
LOGW("CdmEngine::QueryStatus: GetMaxNumberOfOpenSessions failed");
return UNKNOWN_ERROR;
}
@@ -565,7 +682,14 @@ CdmResponseType CdmEngine::QueryStatus(SecurityLevel security_level,
*query_response = max_sessions_stream.str();
} else if (query_token == QUERY_KEY_OEMCRYPTO_API_VERSION) {
uint32_t api_version;
if (!crypto_session.GetApiVersion(&api_version)) {
bool got_version;
M_TIME(
got_version = crypto_session.GetApiVersion(
&api_version),
&metrics_,
crypto_session_get_api_version_,
got_version);
if (!got_version) {
LOGW("CdmEngine::QueryStatus: GetApiVersion failed");
return UNKNOWN_ERROR;
}
@@ -591,7 +715,15 @@ CdmResponseType CdmEngine::QuerySessionStatus(const CdmSessionId& session_id,
session_id.c_str());
return SESSION_NOT_FOUND_8;
}
return iter->second->QueryStatus(query_response);
CdmResponseType sts;
M_TIME(
sts = iter->second->QueryStatus(
query_response),
iter->second->GetMetrics(),
cdm_session_query_status_,
sts);
return sts;
}
bool CdmEngine::IsReleaseSession(const CdmSessionId& session_id) {
@@ -625,7 +757,14 @@ CdmResponseType CdmEngine::QueryKeyStatus(const CdmSessionId& session_id,
session_id.c_str());
return SESSION_NOT_FOUND_9;
}
return iter->second->QueryKeyStatus(query_response);
CdmResponseType sts;
M_TIME(
sts = iter->second->QueryKeyStatus(
query_response),
iter->second->GetMetrics(),
cdm_session_query_key_status_,
sts);
return sts;
}
CdmResponseType CdmEngine::QueryKeyAllowedUsage(const CdmSessionId& session_id,
@@ -642,7 +781,15 @@ CdmResponseType CdmEngine::QueryKeyAllowedUsage(const CdmSessionId& session_id,
session_id.c_str());
return SESSION_NOT_FOUND_12;
}
return iter->second->QueryKeyAllowedUsage(key_id, key_usage);
CdmResponseType sts;
M_TIME(
sts = iter->second->QueryKeyAllowedUsage(
key_id,
key_usage),
iter->second->GetMetrics(),
cdm_session_query_key_allowed_usage_,
sts);
return sts;
}
CdmResponseType CdmEngine::QueryKeyAllowedUsage(const std::string& key_id,
@@ -658,8 +805,13 @@ CdmResponseType CdmEngine::QueryKeyAllowedUsage(const std::string& key_id,
key_usage->Clear();
for (CdmSessionMap::iterator iter = sessions_.begin();
iter != sessions_.end(); ++iter) {
session_sts = iter->second->QueryKeyAllowedUsage(key_id,
&found_in_this_session);
M_TIME(
session_sts = iter->second->QueryKeyAllowedUsage(
key_id,
&found_in_this_session),
iter->second->GetMetrics(),
cdm_session_query_key_allowed_usage_,
session_sts);
if (session_sts == NO_ERROR) {
if (found) {
// Found another key. If usage settings do not match, fail.
@@ -690,7 +842,14 @@ CdmResponseType CdmEngine::QueryOemCryptoSessionId(
session_id.c_str());
return SESSION_NOT_FOUND_10;
}
return iter->second->QueryOemCryptoSessionId(query_response);
CdmResponseType sts;
M_TIME(
sts = iter->second->QueryOemCryptoSessionId(
query_response),
iter->second->GetMetrics(),
cdm_session_query_oemcrypto_session_id_,
sts);
return sts;
}
/*
@@ -715,7 +874,7 @@ CdmResponseType CdmEngine::GetProvisioningRequest(
DeleteAllUsageReportsUponFactoryReset();
if (NULL == cert_provisioning_.get()) {
cert_provisioning_.reset(new CertificateProvisioning());
cert_provisioning_.reset(new CertificateProvisioning(&metrics_));
}
CdmResponseType ret = cert_provisioning_->GetProvisioningRequest(
cert_provisioning_requested_security_level_, cert_type, cert_authority,
@@ -757,16 +916,27 @@ CdmResponseType CdmEngine::HandleProvisioningResponse(
if (NULL == cert_provisioning_.get()) {
// Certificate provisioning object has been released. Check if a concurrent
// provisioning attempt has succeeded before declaring failure.
CryptoSession crypto_session;
CdmResponseType status =
crypto_session.Open(cert_provisioning_requested_security_level_);
CryptoSession crypto_session(&metrics_);
CdmResponseType status;
M_TIME(
status = crypto_session.Open(
cert_provisioning_requested_security_level_),
&metrics_,
crypto_session_open_,
status,
cert_provisioning_requested_security_level_);
if (NO_ERROR != status) {
LOGE(
"CdmEngine::HandleProvisioningResponse: provisioning object "
"missing and crypto session open failed.");
return EMPTY_PROVISIONING_CERTIFICATE_2;
}
CdmSecurityLevel security_level = crypto_session.GetSecurityLevel();
CdmSecurityLevel security_level;
M_TIME(
security_level = crypto_session.GetSecurityLevel(),
&metrics_,
crypto_session_get_security_level_,
security_level);
if (!IsProvisioned(security_level)) {
LOGE(
"CdmEngine::HandleProvisioningResponse: provisioning object "
@@ -814,14 +984,26 @@ CdmResponseType CdmEngine::Unprovision(CdmSecurityLevel security_level) {
return UNPROVISION_ERROR_3;
}
CryptoSession crypto_session;
CdmResponseType status = crypto_session.Open(
CryptoSession crypto_session(&metrics_);
CdmResponseType status;
M_TIME(
status = crypto_session.Open(
security_level == kSecurityLevelL3 ?
kLevel3 :
kLevelDefault),
&metrics_,
crypto_session_open_,
status,
security_level == kSecurityLevelL3 ? kLevel3 : kLevelDefault);
if (NO_ERROR != status) {
LOGE("CdmEngine::Unprovision: error opening crypto session: %d", status);
return UNPROVISION_ERROR_4;
}
status = crypto_session.DeleteAllUsageReports();
M_TIME(
status = crypto_session.DeleteAllUsageReports(),
&metrics_,
crypto_session_delete_all_usage_reports_,
status);
if (status != NO_ERROR) {
LOGE("CdmEngine::Unprovision: error deleteing usage reports: %d", status);
}
@@ -1093,22 +1275,38 @@ CdmResponseType CdmEngine::LoadUsageSession(const CdmKeySetId& key_set_id,
return LOAD_USAGE_INFO_MISSING;
}
CdmResponseType status =
iter->second->RestoreUsageSession(key_message, key_response);
CdmResponseType status;
M_TIME(
status = iter->second->RestoreUsageSession(
key_message,
key_response),
iter->second->GetMetrics(),
cdm_session_restore_usage_session_,
status);
if (KEY_ADDED != status) {
LOGE("CdmEngine::LoadUsageSession: usage session error %ld", status);
return status;
}
CdmKeyRequest request;
status = iter->second->GenerateReleaseRequest(&request);
M_TIME(
status = iter->second->GenerateReleaseRequest(
&request),
iter->second->GetMetrics(),
cdm_session_generate_release_request_,
status);
*release_message = request.message;
switch (status) {
case KEY_MESSAGE:
break;
case KEY_CANCELED: // usage information not present in
iter->second->DeleteLicense(); // OEMCrypto, delete and try again
case KEY_CANCELED:
/* usage information not present in OEMCrypto, delete and try again */
M_TIME(
iter->second->DeleteLicense(),
iter->second->GetMetrics(),
cdm_session_delete_license_);
break;
default:
LOGE("CdmEngine::LoadUsageSession: generate release request error: %d",
@@ -1151,7 +1349,15 @@ CdmResponseType CdmEngine::Decrypt(const CdmSessionId& session_id,
int64_t seconds_remaining = 0;
for (CdmSessionMap::iterator iter = sessions_.begin();
iter != sessions_.end(); ++iter) {
if (iter->second->IsKeyLoaded(*parameters.key_id)) {
bool is_key_loaded;
M_TIME(
is_key_loaded = iter->second->IsKeyLoaded(
*parameters.key_id),
iter->second->GetMetrics(),
cdm_session_is_key_loaded_,
is_key_loaded);
if (is_key_loaded) {
int64_t duration = iter->second->GetDurationRemaining();
if (duration > seconds_remaining) {
session_iter = iter;
@@ -1168,7 +1374,14 @@ CdmResponseType CdmEngine::Decrypt(const CdmSessionId& session_id,
return SESSION_NOT_FOUND_FOR_DECRYPT;
}
return session_iter->second->Decrypt(parameters);
CdmResponseType decrypt_sts;
M_TIME(
decrypt_sts = session_iter->second->Decrypt(
parameters),
session_iter->second->GetMetrics(),
cdm_session_decrypt_,
decrypt_sts);
return decrypt_sts;
}
CdmResponseType CdmEngine::GenericEncrypt(
@@ -1181,8 +1394,20 @@ CdmResponseType CdmEngine::GenericEncrypt(
session_id.c_str());
return SESSION_NOT_FOUND_13;
}
return iter->second->GenericEncrypt(in_buffer, key_id, iv, algorithm,
out_buffer);
CdmResponseType sts;
M_TIME(
sts = iter->second->GenericEncrypt(
in_buffer,
key_id,
iv,
algorithm,
out_buffer),
iter->second->GetMetrics(),
cdm_session_generic_encrypt_,
sts,
metrics::Pow2Bucket(in_buffer.size()),
algorithm);
return sts;
}
CdmResponseType CdmEngine::GenericDecrypt(
@@ -1196,8 +1421,20 @@ CdmResponseType CdmEngine::GenericDecrypt(
session_id.c_str());
return SESSION_NOT_FOUND_14;
}
return iter->second->GenericDecrypt(in_buffer, key_id, iv, algorithm,
out_buffer);
CdmResponseType sts;
M_TIME(
sts = iter->second->GenericDecrypt(
in_buffer,
key_id,
iv,
algorithm,
out_buffer),
iter->second->GetMetrics(),
cdm_session_generic_decrypt_,
sts,
metrics::Pow2Bucket(in_buffer.size()),
algorithm);
return sts;
}
CdmResponseType CdmEngine::GenericSign(
@@ -1210,7 +1447,19 @@ CdmResponseType CdmEngine::GenericSign(
session_id.c_str());
return SESSION_NOT_FOUND_15;
}
return iter->second->GenericSign(message, key_id, algorithm, signature);
CdmResponseType sts;
M_TIME(
sts = iter->second->GenericSign(
message,
key_id,
algorithm,
signature),
iter->second->GetMetrics(),
cdm_session_generic_sign_,
sts,
metrics::Pow2Bucket(message.size()),
algorithm);
return sts;
}
CdmResponseType CdmEngine::GenericVerify(
@@ -1223,7 +1472,19 @@ CdmResponseType CdmEngine::GenericVerify(
session_id.c_str());
return SESSION_NOT_FOUND_16;
}
return iter->second->GenericVerify(message, key_id, algorithm, signature);
CdmResponseType sts;
M_TIME(
sts = iter->second->GenericVerify(
message,
key_id,
algorithm,
signature),
iter->second->GetMetrics(),
cdm_session_generic_verify_,
sts,
metrics::Pow2Bucket(message.size()),
algorithm);
return sts;
}
bool CdmEngine::IsKeyLoaded(const KeyId& key_id) {
@@ -1318,7 +1579,12 @@ void CdmEngine::OnTimerEvent() {
if (!has_usage_been_updated) {
// usage is updated for all sessions so this needs to be
// called only once per update usage information period
CdmResponseType status = iter->second->UpdateUsageInformation();
CdmResponseType status;
M_TIME(
status = iter->second->UpdateUsageInformation(),
iter->second->GetMetrics(),
cdm_session_update_usage_information_,
status);
if (NO_ERROR != status) {
LOGW("Update usage information failed: %d", status);
} else {
@@ -1391,11 +1657,21 @@ void CdmEngine::DeleteAllUsageReportsUponFactoryReset() {
if (!file_system_->Exists(device_base_path_level1) &&
!file_system_->Exists(device_base_path_level3)) {
scoped_ptr<CryptoSession> crypto_session(new CryptoSession());
CdmResponseType status = crypto_session->Open(
scoped_ptr<CryptoSession> crypto_session(new CryptoSession(&metrics_));
CdmResponseType status;
M_TIME(
status = crypto_session->Open(
cert_provisioning_requested_security_level_),
&metrics_,
crypto_session_open_,
status,
cert_provisioning_requested_security_level_);
if (NO_ERROR == status) {
status = crypto_session->DeleteAllUsageReports();
M_TIME(
status = crypto_session->DeleteAllUsageReports(),
&metrics_,
crypto_session_delete_all_usage_reports_,
status);
if (NO_ERROR != status) {
LOGW(
"CdmEngine::GetProvisioningRequest: "