update_engine: UM: Async request expiration handled differently.
As discussed on the tracker issue, we're changing the way an async
policy request expiration timeout is being handled: instead of failing
the policy request entirely, this now only causes the UpdateManager to
dump the evaluation context, reset the expiration deadline and
reevaluate the policy (which is necessary in order for evaluation time
and corresponding timeouts to be recomputed). This is aimed to ensure
that policies are allowed to block for arbitrarily long periods, while
still emitting useful information to the log (which will help diagnose
if this is due to an implementation error).
Since the expiration timeout no longer returns control to the caller, we
remove it from the AsyncPolicyRequest() API. Instead, we use a single
timeout value, which is set during the UpdateManager construction and
used for all policy calls. By default, the update engine sets it to 12
hours; for testing and debugging purposes, a smaller value is used.
This CL also forbids the default (fallback) policy from blocking,
forcing a failure instead; a situation like that makes no sense anyway,
and may lead to inconsistent return values leaking to the caller.
BUG=chromium:401687
TEST=Unit tests.
Change-Id: I0bf60875bb7f524c99ed72dac61720633ab2061b
Reviewed-on: https://chromium-review.googlesource.com/211647
Tested-by: Gilad Arnold <garnold@chromium.org>
Reviewed-by: Alex Vakulenko <avakulenko@chromium.org>
Reviewed-by: Alex Deymo <deymo@chromium.org>
Commit-Queue: Gilad Arnold <garnold@chromium.org>
diff --git a/update_manager/update_manager-inl.h b/update_manager/update_manager-inl.h
index 982ec93..649dcff 100644
--- a/update_manager/update_manager-inl.h
+++ b/update_manager/update_manager-inl.h
@@ -21,43 +21,43 @@
std::string*, R*,
Args...) const,
R* result, Args... args) {
- const std::string policy_name = policy_->PolicyRequestName(policy_method);
- const bool timed_out = ec->is_expired();
+ // If expiration timeout fired, dump the context and reset expiration.
+ // IMPORTANT: We must still proceed with evaluation of the policy in this
+ // case, so that the evaluation time (and corresponding reevaluation timeouts)
+ // are readjusted.
+ if (ec->is_expired()) {
+ LOG(WARNING) << "Request timed out, evaluation context: "
+ << ec->DumpContext();
+ ec->ResetExpiration();
+ }
// Reset the evaluation context.
ec->ResetEvaluation();
- LOG(INFO) << "Evaluating " << policy_name << " START";
+ const std::string policy_name = policy_->PolicyRequestName(policy_method);
+ LOG(INFO) << policy_name << ": START";
- // First try calling the actual policy, if the request did not time out.
- EvalStatus status = EvalStatus::kFailed;
- if (timed_out) {
- LOG(WARNING) << "Skipping reevaluation because the request timed out.";
- } else {
- std::string error;
- status = (policy_.get()->*policy_method)(ec, state_.get(), &error, result,
- args...);
- LOG_IF(WARNING, status == EvalStatus::kFailed)
- << "Evaluating policy failed: " << error
- << "\nEvaluation context: " << ec->DumpContext();
- }
-
+ // First try calling the actual policy.
+ std::string error;
+ EvalStatus status = (policy_.get()->*policy_method)(ec, state_.get(), &error,
+ result, args...);
// If evaluating the main policy failed, defer to the default policy.
if (status == EvalStatus::kFailed) {
- std::string error;
+ LOG(WARNING) << "Evaluating policy failed: " << error
+ << "\nEvaluation context: " << ec->DumpContext();
+ error.clear();
status = (default_policy_.*policy_method)(ec, state_.get(), &error, result,
args...);
- LOG_IF(WARNING, status == EvalStatus::kFailed)
- << "Evaluating default policy failed: " << error;
-
- if (timed_out && status == EvalStatus::kAskMeAgainLater) {
- LOG(WARNING) << "Default policy would block but request timed out, "
- << "forcing failure.";
+ if (status == EvalStatus::kFailed) {
+ LOG(WARNING) << "Evaluating default policy failed: " << error;
+ } else if (status == EvalStatus::kAskMeAgainLater) {
+ LOG(ERROR)
+ << "Default policy would block; this is a bug, forcing failure.";
status = EvalStatus::kFailed;
}
}
- LOG(INFO) << "Evaluating " << policy_name << " END";
+ LOG(INFO) << policy_name << ": END";
return status;
}
@@ -122,13 +122,12 @@
template<typename R, typename... ActualArgs, typename... ExpectedArgs>
void UpdateManager::AsyncPolicyRequest(
base::Callback<void(EvalStatus, const R& result)> callback,
- base::TimeDelta request_timeout,
EvalStatus (Policy::*policy_method)(EvaluationContext*, State*,
std::string*, R*,
ExpectedArgs...) const,
ActualArgs... args) {
scoped_refptr<EvaluationContext> ec =
- new EvaluationContext(clock_, evaluation_timeout_, request_timeout);
+ new EvaluationContext(clock_, evaluation_timeout_, expiration_timeout_);
// IMPORTANT: To ensure that ActualArgs can be converted to ExpectedArgs, we
// explicitly instantiate UpdateManager::OnPolicyReadyToEvaluate with the
// latter in lieu of the former.