Logging CDM session ID on Decrypt() failures.

[ Merge of http://go/wvgerrit/149690 ]

This changes extends the CryptoSession logging to include the OEMCrypto
session ID in its decrypt failure logs, and adds a new CdmSession
decrypt failure log which includes the CDM session ID.  The CDM session
directly maps to the MediaDRM session ID, making app debugging easier.

The Decrypt() code pathway is one of the most frequently called
portions of the CDM code, and the pathway attempts to make as few
logging calls as possible in order to keep latency low and log
verbosity to a minimum.  It is anticiapted that when a call to
Decrypt() fails, there will be a burst of failures as the app may
make several calls to Decrypt() before handling the first decrypt
error.

To keep logging low, the following rules are followed:
- CryptoSession: decrypt errors are only logged when the decrypt error
  changes.
- CdmSession: decrypt errors are only logged when the last call to
  decrypt had succeeded.

Bug: 183984396
Test: MediaGTS with decrypt failures
Change-Id: Ic6124646d129efbc8a690b5bfd4dc422e04e677b
This commit is contained in:
Alex Dale
2022-04-05 19:02:14 -07:00
parent a9fb043c6d
commit f696a48318
3 changed files with 27 additions and 8 deletions

View File

@@ -292,9 +292,17 @@ class CdmSession {
std::string drm_certificate_;
CryptoWrappedKey wrapped_private_key_;
// decryption flags
bool is_initial_decryption_;
bool has_decrypted_since_last_report_; // ... last report to policy engine.
// Decryption flags.
// Indiates that the next call to Decrypt will be the first for this
// license.
bool is_initial_decryption_ = true;
// Set to true if a successful call to Decrypt has occurred. Cleared
// when the policy engine has been notified about successful
// decryption.
bool has_decrypted_since_last_report_ = false;
// Set to true if the last call to Decrypt resulted in a failure.
// Cleared when the call to decrypt has succeeded.
bool last_decrypt_failed_ = false;
// Usage related flags and data
bool is_initial_usage_update_;

View File

@@ -78,8 +78,6 @@ CdmSession::CdmSession(wvutil::FileSystem* file_system,
is_temporary_(false),
security_level_(kSecurityLevelUninitialized),
requested_security_level_(kLevelDefault),
is_initial_decryption_(true),
has_decrypted_since_last_report_(false),
is_initial_usage_update_(true),
is_usage_update_needed_(false),
usage_table_header_(nullptr),
@@ -694,7 +692,7 @@ CdmResponseType CdmSession::Decrypt(const CdmDecryptionParametersV16& params) {
}
}
CdmResponseType status = crypto_session_->Decrypt(params);
const CdmResponseType status = crypto_session_->Decrypt(params);
if (status == NO_ERROR) {
if (is_initial_decryption_) {
@@ -704,9 +702,17 @@ CdmResponseType CdmSession::Decrypt(const CdmDecryptionParametersV16& params) {
if (!is_usage_update_needed_) {
is_usage_update_needed_ = has_provider_session_token();
}
last_decrypt_failed_ = false;
} else {
if (!last_decrypt_failed_) {
// Only log on the first failure. Certain failures are likely
// to occur in succession of each other.
LOGE("Decryption failed: sid = %s, status = %d", IdToString(session_id_),
static_cast<int>(status));
}
last_decrypt_failed_ = true;
wvutil::Clock clock;
int64_t current_time = clock.GetCurrentTime();
const int64_t current_time = clock.GetCurrentTime();
if (policy_engine_->HasLicenseOrRentalOrPlaybackDurationExpired(
current_time)) {
return NEED_KEY;

View File

@@ -1823,7 +1823,12 @@ CdmResponseType CryptoSession::Decrypt(
"oec_session_id = %u",
oec_session_id_);
} else {
LOGE("OEMCrypto_DecryptCENC failed: status = %d", static_cast<int>(sts));
LOGE(
"OEMCrypto_DecryptCENC failed: oec_session_id = %u, "
"security_level = %s, status = %d",
oec_session_id_,
RequestedSecurityLevelToString(requested_security_level_),
static_cast<int>(sts));
}
}