blob: 975ba15c43aa6a74e7dd40b646e12280203d0c3b [file] [log] [blame]
Jay Srinivasan6f6ea002012-12-14 11:26:28 -08001// Copyright (c) 2012 The Chromium OS Authors. All rights reserved.
2// Use of this source code is governed by a BSD-style license that can be
3// found in the LICENSE file.
4
5#include "update_engine/payload_state.h"
6
Jay Srinivasan08262882012-12-28 19:29:43 -08007#include <algorithm>
8
Jay Srinivasan6f6ea002012-12-14 11:26:28 -08009#include <base/logging.h>
Alex Vakulenko75039d72014-03-25 12:36:28 -070010#include <base/strings/string_util.h>
11#include <base/strings/stringprintf.h>
12#include <base/format_macros.h>
Gilad Arnold1f847232014-04-07 12:07:49 -070013#include <policy/device_policy.h>
Jay Srinivasan6f6ea002012-12-14 11:26:28 -080014
David Zeuthenf413fe52013-04-22 14:04:39 -070015#include "update_engine/clock.h"
Jay Srinivasand29695d2013-04-08 15:08:05 -070016#include "update_engine/constants.h"
Alex Deymo42432912013-07-12 20:21:15 -070017#include "update_engine/hardware_interface.h"
18#include "update_engine/install_plan.h"
Gilad Arnold1f847232014-04-07 12:07:49 -070019#include "update_engine/omaha_request_params.h"
Jay Srinivasan19409b72013-04-12 19:23:36 -070020#include "update_engine/prefs.h"
David Zeuthenb281f072014-04-02 10:20:19 -070021#include "update_engine/real_dbus_wrapper.h"
Jay Srinivasan19409b72013-04-12 19:23:36 -070022#include "update_engine/system_state.h"
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -080023#include "update_engine/utils.h"
Jay Srinivasan6f6ea002012-12-14 11:26:28 -080024
Jay Srinivasan08262882012-12-28 19:29:43 -080025using base::Time;
26using base::TimeDelta;
27using std::min;
Jay Srinivasan6f6ea002012-12-14 11:26:28 -080028using std::string;
29
30namespace chromeos_update_engine {
31
David Zeuthen9a017f22013-04-11 16:10:26 -070032const TimeDelta PayloadState::kDurationSlack = TimeDelta::FromSeconds(600);
33
Jay Srinivasan08262882012-12-28 19:29:43 -080034// We want to upperbound backoffs to 16 days
Alex Deymo820cc702013-06-28 15:43:46 -070035static const int kMaxBackoffDays = 16;
Jay Srinivasan6f6ea002012-12-14 11:26:28 -080036
Jay Srinivasan08262882012-12-28 19:29:43 -080037// We want to randomize retry attempts after the backoff by +/- 6 hours.
38static const uint32_t kMaxBackoffFuzzMinutes = 12 * 60;
Jay Srinivasan6f6ea002012-12-14 11:26:28 -080039
Jay Srinivasan19409b72013-04-12 19:23:36 -070040PayloadState::PayloadState()
41 : prefs_(NULL),
David Zeuthenbb8bdc72013-09-03 13:43:48 -070042 using_p2p_for_downloading_(false),
Jay Srinivasan19409b72013-04-12 19:23:36 -070043 payload_attempt_number_(0),
Alex Deymo820cc702013-06-28 15:43:46 -070044 full_payload_attempt_number_(0),
Jay Srinivasan19409b72013-04-12 19:23:36 -070045 url_index_(0),
David Zeuthencc6f9962013-04-18 11:57:24 -070046 url_failure_count_(0),
David Zeuthendcba8092013-08-06 12:16:35 -070047 url_switch_count_(0),
David Zeuthenafed4a12014-04-09 15:28:44 -070048 p2p_num_attempts_(0),
49 attempt_num_bytes_downloaded_(0),
50 attempt_connection_type_(metrics::ConnectionType::kUnknown),
51 attempt_type_(AttemptType::kUpdate)
52{
Jay Srinivasan19409b72013-04-12 19:23:36 -070053 for (int i = 0; i <= kNumDownloadSources; i++)
54 total_bytes_downloaded_[i] = current_bytes_downloaded_[i] = 0;
55}
56
57bool PayloadState::Initialize(SystemState* system_state) {
58 system_state_ = system_state;
59 prefs_ = system_state_->prefs();
Chris Sosaaa18e162013-06-20 13:20:30 -070060 powerwash_safe_prefs_ = system_state_->powerwash_safe_prefs();
Jay Srinivasan08262882012-12-28 19:29:43 -080061 LoadResponseSignature();
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -080062 LoadPayloadAttemptNumber();
Alex Deymo820cc702013-06-28 15:43:46 -070063 LoadFullPayloadAttemptNumber();
Jay Srinivasan6f6ea002012-12-14 11:26:28 -080064 LoadUrlIndex();
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -080065 LoadUrlFailureCount();
David Zeuthencc6f9962013-04-18 11:57:24 -070066 LoadUrlSwitchCount();
Jay Srinivasan08262882012-12-28 19:29:43 -080067 LoadBackoffExpiryTime();
David Zeuthen9a017f22013-04-11 16:10:26 -070068 LoadUpdateTimestampStart();
69 // The LoadUpdateDurationUptime() method relies on LoadUpdateTimestampStart()
70 // being called before it. Don't reorder.
71 LoadUpdateDurationUptime();
Jay Srinivasan19409b72013-04-12 19:23:36 -070072 for (int i = 0; i < kNumDownloadSources; i++) {
73 DownloadSource source = static_cast<DownloadSource>(i);
74 LoadCurrentBytesDownloaded(source);
75 LoadTotalBytesDownloaded(source);
76 }
Chris Sosabe45bef2013-04-09 18:25:12 -070077 LoadNumReboots();
David Zeuthena573d6f2013-06-14 16:13:36 -070078 LoadNumResponsesSeen();
Chris Sosaaa18e162013-06-20 13:20:30 -070079 LoadRollbackVersion();
David Zeuthendcba8092013-08-06 12:16:35 -070080 LoadP2PFirstAttemptTimestamp();
81 LoadP2PNumAttempts();
Jay Srinivasan6f6ea002012-12-14 11:26:28 -080082 return true;
83}
84
Jay Srinivasan6f6ea002012-12-14 11:26:28 -080085void PayloadState::SetResponse(const OmahaResponse& omaha_response) {
Jay Srinivasan08262882012-12-28 19:29:43 -080086 // Always store the latest response.
87 response_ = omaha_response;
Jay Srinivasan6f6ea002012-12-14 11:26:28 -080088
Jay Srinivasan53173b92013-05-17 17:13:01 -070089 // Compute the candidate URLs first as they are used to calculate the
90 // response signature so that a change in enterprise policy for
91 // HTTP downloads being enabled or not could be honored as soon as the
92 // next update check happens.
93 ComputeCandidateUrls();
94
Jay Srinivasan08262882012-12-28 19:29:43 -080095 // Check if the "signature" of this response (i.e. the fields we care about)
96 // has changed.
97 string new_response_signature = CalculateResponseSignature();
98 bool has_response_changed = (response_signature_ != new_response_signature);
99
100 // If the response has changed, we should persist the new signature and
101 // clear away all the existing state.
Jay Srinivasan6f6ea002012-12-14 11:26:28 -0800102 if (has_response_changed) {
Jay Srinivasan08262882012-12-28 19:29:43 -0800103 LOG(INFO) << "Resetting all persisted state as this is a new response";
David Zeuthena573d6f2013-06-14 16:13:36 -0700104 SetNumResponsesSeen(num_responses_seen_ + 1);
Jay Srinivasan08262882012-12-28 19:29:43 -0800105 SetResponseSignature(new_response_signature);
106 ResetPersistedState();
Alex Deymob33b0f02013-08-08 21:10:02 -0700107 ReportUpdatesAbandonedEventCountMetric();
Jay Srinivasan08262882012-12-28 19:29:43 -0800108 return;
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800109 }
110
Jay Srinivasan08262882012-12-28 19:29:43 -0800111 // This is the earliest point at which we can validate whether the URL index
112 // we loaded from the persisted state is a valid value. If the response
113 // hasn't changed but the URL index is invalid, it's indicative of some
114 // tampering of the persisted state.
Jay Srinivasan53173b92013-05-17 17:13:01 -0700115 if (static_cast<uint32_t>(url_index_) >= candidate_urls_.size()) {
Jay Srinivasan08262882012-12-28 19:29:43 -0800116 LOG(INFO) << "Resetting all payload state as the url index seems to have "
117 "been tampered with";
118 ResetPersistedState();
119 return;
Jay Srinivasan6f6ea002012-12-14 11:26:28 -0800120 }
Jay Srinivasan19409b72013-04-12 19:23:36 -0700121
122 // Update the current download source which depends on the latest value of
123 // the response.
124 UpdateCurrentDownloadSource();
Jay Srinivasan6f6ea002012-12-14 11:26:28 -0800125}
126
David Zeuthenbb8bdc72013-09-03 13:43:48 -0700127void PayloadState::SetUsingP2PForDownloading(bool value) {
128 using_p2p_for_downloading_ = value;
129 // Update the current download source which depends on whether we are
130 // using p2p or not.
131 UpdateCurrentDownloadSource();
132}
133
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800134void PayloadState::DownloadComplete() {
135 LOG(INFO) << "Payload downloaded successfully";
136 IncrementPayloadAttemptNumber();
Alex Deymo820cc702013-06-28 15:43:46 -0700137 IncrementFullPayloadAttemptNumber();
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800138}
139
140void PayloadState::DownloadProgress(size_t count) {
141 if (count == 0)
142 return;
143
David Zeuthen9a017f22013-04-11 16:10:26 -0700144 CalculateUpdateDurationUptime();
Jay Srinivasan19409b72013-04-12 19:23:36 -0700145 UpdateBytesDownloaded(count);
David Zeuthen9a017f22013-04-11 16:10:26 -0700146
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800147 // We've received non-zero bytes from a recent download operation. Since our
148 // URL failure count is meant to penalize a URL only for consecutive
149 // failures, downloading bytes successfully means we should reset the failure
150 // count (as we know at least that the URL is working). In future, we can
151 // design this to be more sophisticated to check for more intelligent failure
152 // patterns, but right now, even 1 byte downloaded will mark the URL to be
153 // good unless it hits 10 (or configured number of) consecutive failures
154 // again.
155
156 if (GetUrlFailureCount() == 0)
157 return;
158
159 LOG(INFO) << "Resetting failure count of Url" << GetUrlIndex()
160 << " to 0 as we received " << count << " bytes successfully";
161 SetUrlFailureCount(0);
162}
163
David Zeuthenafed4a12014-04-09 15:28:44 -0700164void PayloadState::AttemptStarted(AttemptType attempt_type) {
David Zeuthen4e1d1492014-04-25 13:12:27 -0700165 // Flush previous state from abnormal attempt failure, if any.
166 ReportAndClearPersistedAttemptMetrics();
167
David Zeuthenafed4a12014-04-09 15:28:44 -0700168 attempt_type_ = attempt_type;
169
David Zeuthen33bae492014-02-25 16:16:18 -0800170 ClockInterface *clock = system_state_->clock();
171 attempt_start_time_boot_ = clock->GetBootTime();
172 attempt_start_time_monotonic_ = clock->GetMonotonicTime();
David Zeuthen33bae492014-02-25 16:16:18 -0800173 attempt_num_bytes_downloaded_ = 0;
David Zeuthenb281f072014-04-02 10:20:19 -0700174
175 metrics::ConnectionType type;
176 NetworkConnectionType network_connection_type;
177 NetworkTethering tethering;
178 RealDBusWrapper dbus_iface;
179 ConnectionManager* connection_manager = system_state_->connection_manager();
180 if (!connection_manager->GetConnectionProperties(&dbus_iface,
181 &network_connection_type,
182 &tethering)) {
183 LOG(ERROR) << "Failed to determine connection type.";
184 type = metrics::ConnectionType::kUnknown;
185 } else {
186 type = utils::GetConnectionType(network_connection_type, tethering);
187 }
188 attempt_connection_type_ = type;
David Zeuthen4e1d1492014-04-25 13:12:27 -0700189
190 if (attempt_type == AttemptType::kUpdate)
191 PersistAttemptMetrics();
David Zeuthen33bae492014-02-25 16:16:18 -0800192}
193
Chris Sosabe45bef2013-04-09 18:25:12 -0700194void PayloadState::UpdateResumed() {
195 LOG(INFO) << "Resuming an update that was previously started.";
196 UpdateNumReboots();
David Zeuthenafed4a12014-04-09 15:28:44 -0700197 AttemptStarted(AttemptType::kUpdate);
Chris Sosabe45bef2013-04-09 18:25:12 -0700198}
199
Jay Srinivasan19409b72013-04-12 19:23:36 -0700200void PayloadState::UpdateRestarted() {
201 LOG(INFO) << "Starting a new update";
202 ResetDownloadSourcesOnNewUpdate();
Chris Sosabe45bef2013-04-09 18:25:12 -0700203 SetNumReboots(0);
David Zeuthenafed4a12014-04-09 15:28:44 -0700204 AttemptStarted(AttemptType::kUpdate);
Jay Srinivasan19409b72013-04-12 19:23:36 -0700205}
206
David Zeuthen9a017f22013-04-11 16:10:26 -0700207void PayloadState::UpdateSucceeded() {
Jay Srinivasan19409b72013-04-12 19:23:36 -0700208 // Send the relevant metrics that are tracked in this class to UMA.
David Zeuthen9a017f22013-04-11 16:10:26 -0700209 CalculateUpdateDurationUptime();
David Zeuthenf413fe52013-04-22 14:04:39 -0700210 SetUpdateTimestampEnd(system_state_->clock()->GetWallclockTime());
David Zeuthen33bae492014-02-25 16:16:18 -0800211
David Zeuthen96197df2014-04-16 12:22:39 -0700212 switch (attempt_type_) {
213 case AttemptType::kUpdate:
214 CollectAndReportAttemptMetrics(kErrorCodeSuccess);
215 CollectAndReportSuccessfulUpdateMetrics();
David Zeuthen4e1d1492014-04-25 13:12:27 -0700216 ClearPersistedAttemptMetrics();
David Zeuthen96197df2014-04-16 12:22:39 -0700217 break;
218
219 case AttemptType::kRollback:
220 metrics::ReportRollbackMetrics(system_state_,
221 metrics::RollbackResult::kSuccess);
222 break;
David Zeuthenafed4a12014-04-09 15:28:44 -0700223 }
David Zeuthena573d6f2013-06-14 16:13:36 -0700224
225 // Reset the number of responses seen since it counts from the last
226 // successful update, e.g. now.
227 SetNumResponsesSeen(0);
David Zeuthene4c58bf2013-06-18 17:26:50 -0700228
229 CreateSystemUpdatedMarkerFile();
David Zeuthen9a017f22013-04-11 16:10:26 -0700230}
231
David Zeuthena99981f2013-04-29 13:42:47 -0700232void PayloadState::UpdateFailed(ErrorCode error) {
233 ErrorCode base_error = utils::GetBaseErrorCode(error);
Jay Srinivasan55f50c22013-01-10 19:24:35 -0800234 LOG(INFO) << "Updating payload state for error code: " << base_error
235 << " (" << utils::CodeToString(base_error) << ")";
Jay Srinivasan6f6ea002012-12-14 11:26:28 -0800236
Jay Srinivasan53173b92013-05-17 17:13:01 -0700237 if (candidate_urls_.size() == 0) {
238 // This means we got this error even before we got a valid Omaha response
239 // or don't have any valid candidates in the Omaha response.
Jay Srinivasan08262882012-12-28 19:29:43 -0800240 // So we should not advance the url_index_ in such cases.
Jay Srinivasan6f6ea002012-12-14 11:26:28 -0800241 LOG(INFO) << "Ignoring failures until we get a valid Omaha response.";
242 return;
243 }
244
David Zeuthen96197df2014-04-16 12:22:39 -0700245 switch (attempt_type_) {
246 case AttemptType::kUpdate:
247 CollectAndReportAttemptMetrics(base_error);
David Zeuthen4e1d1492014-04-25 13:12:27 -0700248 ClearPersistedAttemptMetrics();
David Zeuthen96197df2014-04-16 12:22:39 -0700249 break;
250
251 case AttemptType::kRollback:
252 metrics::ReportRollbackMetrics(system_state_,
253 metrics::RollbackResult::kFailed);
254 break;
255 }
David Zeuthen33bae492014-02-25 16:16:18 -0800256
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800257 switch (base_error) {
258 // Errors which are good indicators of a problem with a particular URL or
259 // the protocol used in the URL or entities in the communication channel
260 // (e.g. proxies). We should try the next available URL in the next update
261 // check to quickly recover from these errors.
David Zeuthena99981f2013-04-29 13:42:47 -0700262 case kErrorCodePayloadHashMismatchError:
263 case kErrorCodePayloadSizeMismatchError:
264 case kErrorCodeDownloadPayloadVerificationError:
265 case kErrorCodeDownloadPayloadPubKeyVerificationError:
266 case kErrorCodeSignedDeltaPayloadExpectedError:
267 case kErrorCodeDownloadInvalidMetadataMagicString:
268 case kErrorCodeDownloadSignatureMissingInManifest:
269 case kErrorCodeDownloadManifestParseError:
270 case kErrorCodeDownloadMetadataSignatureError:
271 case kErrorCodeDownloadMetadataSignatureVerificationError:
272 case kErrorCodeDownloadMetadataSignatureMismatch:
273 case kErrorCodeDownloadOperationHashVerificationError:
274 case kErrorCodeDownloadOperationExecutionError:
275 case kErrorCodeDownloadOperationHashMismatch:
276 case kErrorCodeDownloadInvalidMetadataSize:
277 case kErrorCodeDownloadInvalidMetadataSignature:
278 case kErrorCodeDownloadOperationHashMissingError:
279 case kErrorCodeDownloadMetadataSignatureMissingError:
Gilad Arnold21504f02013-05-24 08:51:22 -0700280 case kErrorCodePayloadMismatchedType:
Don Garrett4d039442013-10-28 18:40:06 -0700281 case kErrorCodeUnsupportedMajorPayloadVersion:
282 case kErrorCodeUnsupportedMinorPayloadVersion:
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800283 IncrementUrlIndex();
284 break;
285
286 // Errors which seem to be just transient network/communication related
287 // failures and do not indicate any inherent problem with the URL itself.
288 // So, we should keep the current URL but just increment the
289 // failure count to give it more chances. This way, while we maximize our
290 // chances of downloading from the URLs that appear earlier in the response
291 // (because download from a local server URL that appears earlier in a
292 // response is preferable than downloading from the next URL which could be
293 // a internet URL and thus could be more expensive).
David Zeuthena99981f2013-04-29 13:42:47 -0700294 case kErrorCodeError:
295 case kErrorCodeDownloadTransferError:
296 case kErrorCodeDownloadWriteError:
297 case kErrorCodeDownloadStateInitializationError:
298 case kErrorCodeOmahaErrorInHTTPResponse: // Aggregate code for HTTP errors.
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800299 IncrementFailureCount();
300 break;
301
302 // Errors which are not specific to a URL and hence shouldn't result in
303 // the URL being penalized. This can happen in two cases:
304 // 1. We haven't started downloading anything: These errors don't cost us
305 // anything in terms of actual payload bytes, so we should just do the
306 // regular retries at the next update check.
307 // 2. We have successfully downloaded the payload: In this case, the
308 // payload attempt number would have been incremented and would take care
Jay Srinivasan08262882012-12-28 19:29:43 -0800309 // of the backoff at the next update check.
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800310 // In either case, there's no need to update URL index or failure count.
David Zeuthena99981f2013-04-29 13:42:47 -0700311 case kErrorCodeOmahaRequestError:
312 case kErrorCodeOmahaResponseHandlerError:
313 case kErrorCodePostinstallRunnerError:
314 case kErrorCodeFilesystemCopierError:
315 case kErrorCodeInstallDeviceOpenError:
316 case kErrorCodeKernelDeviceOpenError:
317 case kErrorCodeDownloadNewPartitionInfoError:
318 case kErrorCodeNewRootfsVerificationError:
319 case kErrorCodeNewKernelVerificationError:
320 case kErrorCodePostinstallBootedFromFirmwareB:
Don Garrett81018e02013-07-30 18:46:31 -0700321 case kErrorCodePostinstallFirmwareRONotUpdatable:
David Zeuthena99981f2013-04-29 13:42:47 -0700322 case kErrorCodeOmahaRequestEmptyResponseError:
323 case kErrorCodeOmahaRequestXMLParseError:
324 case kErrorCodeOmahaResponseInvalid:
325 case kErrorCodeOmahaUpdateIgnoredPerPolicy:
326 case kErrorCodeOmahaUpdateDeferredPerPolicy:
327 case kErrorCodeOmahaUpdateDeferredForBackoff:
328 case kErrorCodePostinstallPowerwashError:
329 case kErrorCodeUpdateCanceledByChannelChange:
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800330 LOG(INFO) << "Not incrementing URL index or failure count for this error";
331 break;
332
David Zeuthena99981f2013-04-29 13:42:47 -0700333 case kErrorCodeSuccess: // success code
David Zeuthena99981f2013-04-29 13:42:47 -0700334 case kErrorCodeUmaReportedMax: // not an error code
335 case kErrorCodeOmahaRequestHTTPResponseBase: // aggregated already
336 case kErrorCodeDevModeFlag: // not an error code
337 case kErrorCodeResumedFlag: // not an error code
338 case kErrorCodeTestImageFlag: // not an error code
339 case kErrorCodeTestOmahaUrlFlag: // not an error code
340 case kErrorCodeSpecialFlags: // not an error code
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800341 // These shouldn't happen. Enumerating these explicitly here so that we
342 // can let the compiler warn about new error codes that are added to
343 // action_processor.h but not added here.
344 LOG(WARNING) << "Unexpected error code for UpdateFailed";
345 break;
346
347 // Note: Not adding a default here so as to let the compiler warn us of
348 // any new enums that were added in the .h but not listed in this switch.
349 }
350}
351
Jay Srinivasan08262882012-12-28 19:29:43 -0800352bool PayloadState::ShouldBackoffDownload() {
353 if (response_.disable_payload_backoff) {
354 LOG(INFO) << "Payload backoff logic is disabled. "
355 "Can proceed with the download";
356 return false;
357 }
Chris Sosa20f005c2013-09-05 13:53:08 -0700358 if (system_state_->request_params()->use_p2p_for_downloading() &&
359 !system_state_->request_params()->p2p_url().empty()) {
360 LOG(INFO) << "Payload backoff logic is disabled because download "
361 << "will happen from local peer (via p2p).";
362 return false;
363 }
364 if (system_state_->request_params()->interactive()) {
365 LOG(INFO) << "Payload backoff disabled for interactive update checks.";
366 return false;
367 }
Jay Srinivasan08262882012-12-28 19:29:43 -0800368 if (response_.is_delta_payload) {
369 // If delta payloads fail, we want to fallback quickly to full payloads as
370 // they are more likely to succeed. Exponential backoffs would greatly
371 // slow down the fallback to full payloads. So we don't backoff for delta
372 // payloads.
373 LOG(INFO) << "No backoffs for delta payloads. "
374 << "Can proceed with the download";
375 return false;
376 }
377
J. Richard Barnette056b0ab2013-10-29 15:24:56 -0700378 if (!system_state_->hardware()->IsOfficialBuild()) {
Jay Srinivasan08262882012-12-28 19:29:43 -0800379 // Backoffs are needed only for official builds. We do not want any delays
380 // or update failures due to backoffs during testing or development.
381 LOG(INFO) << "No backoffs for test/dev images. "
382 << "Can proceed with the download";
383 return false;
384 }
385
386 if (backoff_expiry_time_.is_null()) {
387 LOG(INFO) << "No backoff expiry time has been set. "
388 << "Can proceed with the download";
389 return false;
390 }
391
392 if (backoff_expiry_time_ < Time::Now()) {
393 LOG(INFO) << "The backoff expiry time ("
394 << utils::ToString(backoff_expiry_time_)
395 << ") has elapsed. Can proceed with the download";
396 return false;
397 }
398
399 LOG(INFO) << "Cannot proceed with downloads as we need to backoff until "
400 << utils::ToString(backoff_expiry_time_);
401 return true;
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800402}
403
Chris Sosaaa18e162013-06-20 13:20:30 -0700404void PayloadState::Rollback() {
405 SetRollbackVersion(system_state_->request_params()->app_version());
David Zeuthenafed4a12014-04-09 15:28:44 -0700406 AttemptStarted(AttemptType::kRollback);
Chris Sosaaa18e162013-06-20 13:20:30 -0700407}
408
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800409void PayloadState::IncrementPayloadAttemptNumber() {
Alex Deymo820cc702013-06-28 15:43:46 -0700410 // Update the payload attempt number for both payload types: full and delta.
411 SetPayloadAttemptNumber(GetPayloadAttemptNumber() + 1);
Alex Deymo29b51d92013-07-09 15:26:24 -0700412
413 // Report the metric every time the value is incremented.
414 string metric = "Installer.PayloadAttemptNumber";
415 int value = GetPayloadAttemptNumber();
416
417 LOG(INFO) << "Uploading " << value << " (count) for metric " << metric;
418 system_state_->metrics_lib()->SendToUMA(
419 metric,
420 value,
421 1, // min value
422 50, // max value
423 kNumDefaultUmaBuckets);
Alex Deymo820cc702013-06-28 15:43:46 -0700424}
425
426void PayloadState::IncrementFullPayloadAttemptNumber() {
427 // Update the payload attempt number for full payloads and the backoff time.
Jay Srinivasan08262882012-12-28 19:29:43 -0800428 if (response_.is_delta_payload) {
429 LOG(INFO) << "Not incrementing payload attempt number for delta payloads";
430 return;
431 }
432
Alex Deymo29b51d92013-07-09 15:26:24 -0700433 LOG(INFO) << "Incrementing the full payload attempt number";
Alex Deymo820cc702013-06-28 15:43:46 -0700434 SetFullPayloadAttemptNumber(GetFullPayloadAttemptNumber() + 1);
Jay Srinivasan08262882012-12-28 19:29:43 -0800435 UpdateBackoffExpiryTime();
Alex Deymo29b51d92013-07-09 15:26:24 -0700436
437 // Report the metric every time the value is incremented.
438 string metric = "Installer.FullPayloadAttemptNumber";
439 int value = GetFullPayloadAttemptNumber();
440
441 LOG(INFO) << "Uploading " << value << " (count) for metric " << metric;
442 system_state_->metrics_lib()->SendToUMA(
443 metric,
444 value,
445 1, // min value
446 50, // max value
447 kNumDefaultUmaBuckets);
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800448}
449
450void PayloadState::IncrementUrlIndex() {
Jay Srinivasan6f6ea002012-12-14 11:26:28 -0800451 uint32_t next_url_index = GetUrlIndex() + 1;
Jay Srinivasan53173b92013-05-17 17:13:01 -0700452 if (next_url_index < candidate_urls_.size()) {
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800453 LOG(INFO) << "Incrementing the URL index for next attempt";
454 SetUrlIndex(next_url_index);
Jay Srinivasan6f6ea002012-12-14 11:26:28 -0800455 } else {
456 LOG(INFO) << "Resetting the current URL index (" << GetUrlIndex() << ") to "
Jay Srinivasan53173b92013-05-17 17:13:01 -0700457 << "0 as we only have " << candidate_urls_.size()
458 << " candidate URL(s)";
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800459 SetUrlIndex(0);
Alex Deymo29b51d92013-07-09 15:26:24 -0700460 IncrementPayloadAttemptNumber();
461 IncrementFullPayloadAttemptNumber();
Jay Srinivasan6f6ea002012-12-14 11:26:28 -0800462 }
Jay Srinivasan08262882012-12-28 19:29:43 -0800463
David Zeuthencc6f9962013-04-18 11:57:24 -0700464 // If we have multiple URLs, record that we just switched to another one
Jay Srinivasan53173b92013-05-17 17:13:01 -0700465 if (candidate_urls_.size() > 1)
David Zeuthencc6f9962013-04-18 11:57:24 -0700466 SetUrlSwitchCount(url_switch_count_ + 1);
467
Jay Srinivasan08262882012-12-28 19:29:43 -0800468 // Whenever we update the URL index, we should also clear the URL failure
469 // count so we can start over fresh for the new URL.
470 SetUrlFailureCount(0);
Jay Srinivasan6f6ea002012-12-14 11:26:28 -0800471}
472
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800473void PayloadState::IncrementFailureCount() {
474 uint32_t next_url_failure_count = GetUrlFailureCount() + 1;
Jay Srinivasan08262882012-12-28 19:29:43 -0800475 if (next_url_failure_count < response_.max_failure_count_per_url) {
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800476 LOG(INFO) << "Incrementing the URL failure count";
477 SetUrlFailureCount(next_url_failure_count);
478 } else {
479 LOG(INFO) << "Reached max number of failures for Url" << GetUrlIndex()
480 << ". Trying next available URL";
481 IncrementUrlIndex();
482 }
483}
484
Jay Srinivasan08262882012-12-28 19:29:43 -0800485void PayloadState::UpdateBackoffExpiryTime() {
486 if (response_.disable_payload_backoff) {
487 LOG(INFO) << "Resetting backoff expiry time as payload backoff is disabled";
488 SetBackoffExpiryTime(Time());
489 return;
490 }
491
Alex Deymo820cc702013-06-28 15:43:46 -0700492 if (GetFullPayloadAttemptNumber() == 0) {
Jay Srinivasan08262882012-12-28 19:29:43 -0800493 SetBackoffExpiryTime(Time());
494 return;
495 }
496
497 // Since we're doing left-shift below, make sure we don't shift more
Alex Deymo820cc702013-06-28 15:43:46 -0700498 // than this. E.g. if int is 4-bytes, don't left-shift more than 30 bits,
Jay Srinivasan08262882012-12-28 19:29:43 -0800499 // since we don't expect value of kMaxBackoffDays to be more than 100 anyway.
Alex Deymo820cc702013-06-28 15:43:46 -0700500 int num_days = 1; // the value to be shifted.
501 const int kMaxShifts = (sizeof(num_days) * 8) - 2;
Jay Srinivasan08262882012-12-28 19:29:43 -0800502
503 // Normal backoff days is 2 raised to (payload_attempt_number - 1).
504 // E.g. if payload_attempt_number is over 30, limit power to 30.
Alex Deymo820cc702013-06-28 15:43:46 -0700505 int power = min(GetFullPayloadAttemptNumber() - 1, kMaxShifts);
Jay Srinivasan08262882012-12-28 19:29:43 -0800506
507 // The number of days is the minimum of 2 raised to (payload_attempt_number
508 // - 1) or kMaxBackoffDays.
509 num_days = min(num_days << power, kMaxBackoffDays);
510
511 // We don't want all retries to happen exactly at the same time when
512 // retrying after backoff. So add some random minutes to fuzz.
513 int fuzz_minutes = utils::FuzzInt(0, kMaxBackoffFuzzMinutes);
514 TimeDelta next_backoff_interval = TimeDelta::FromDays(num_days) +
515 TimeDelta::FromMinutes(fuzz_minutes);
516 LOG(INFO) << "Incrementing the backoff expiry time by "
517 << utils::FormatTimeDelta(next_backoff_interval);
518 SetBackoffExpiryTime(Time::Now() + next_backoff_interval);
519}
520
Jay Srinivasan19409b72013-04-12 19:23:36 -0700521void PayloadState::UpdateCurrentDownloadSource() {
522 current_download_source_ = kNumDownloadSources;
523
David Zeuthenbb8bdc72013-09-03 13:43:48 -0700524 if (using_p2p_for_downloading_) {
525 current_download_source_ = kDownloadSourceHttpPeer;
526 } else if (GetUrlIndex() < candidate_urls_.size()) {
Jay Srinivasan53173b92013-05-17 17:13:01 -0700527 string current_url = candidate_urls_[GetUrlIndex()];
Jay Srinivasan19409b72013-04-12 19:23:36 -0700528 if (StartsWithASCII(current_url, "https://", false))
529 current_download_source_ = kDownloadSourceHttpsServer;
530 else if (StartsWithASCII(current_url, "http://", false))
531 current_download_source_ = kDownloadSourceHttpServer;
532 }
533
534 LOG(INFO) << "Current download source: "
535 << utils::ToString(current_download_source_);
536}
537
538void PayloadState::UpdateBytesDownloaded(size_t count) {
539 SetCurrentBytesDownloaded(
540 current_download_source_,
541 GetCurrentBytesDownloaded(current_download_source_) + count,
542 false);
543 SetTotalBytesDownloaded(
544 current_download_source_,
545 GetTotalBytesDownloaded(current_download_source_) + count,
546 false);
David Zeuthen33bae492014-02-25 16:16:18 -0800547
548 attempt_num_bytes_downloaded_ += count;
Jay Srinivasan19409b72013-04-12 19:23:36 -0700549}
550
David Zeuthen33bae492014-02-25 16:16:18 -0800551PayloadType PayloadState::CalculatePayloadType() {
552 PayloadType payload_type;
553 OmahaRequestParams* params = system_state_->request_params();
554 if (response_.is_delta_payload) {
555 payload_type = kPayloadTypeDelta;
556 } else if (params->delta_okay()) {
557 payload_type = kPayloadTypeFull;
558 } else { // Full payload, delta was not allowed by request.
559 payload_type = kPayloadTypeForcedFull;
560 }
561 return payload_type;
562}
563
564// TODO(zeuthen): Currently we don't report the UpdateEngine.Attempt.*
565// metrics if the attempt ends abnormally, e.g. if the update_engine
566// process crashes or the device is rebooted. See
567// http://crbug.com/357676
568void PayloadState::CollectAndReportAttemptMetrics(ErrorCode code) {
569 int attempt_number = GetPayloadAttemptNumber();
570
571 PayloadType payload_type = CalculatePayloadType();
572
573 int64_t payload_size = response_.size;
574
575 int64_t payload_bytes_downloaded = attempt_num_bytes_downloaded_;
576
577 ClockInterface *clock = system_state_->clock();
578 base::TimeDelta duration = clock->GetBootTime() - attempt_start_time_boot_;
579 base::TimeDelta duration_uptime = clock->GetMonotonicTime() -
580 attempt_start_time_monotonic_;
581
582 int64_t payload_download_speed_bps = 0;
583 int64_t usec = duration_uptime.InMicroseconds();
584 if (usec > 0) {
585 double sec = static_cast<double>(usec) / Time::kMicrosecondsPerSecond;
586 double bps = static_cast<double>(payload_bytes_downloaded) / sec;
587 payload_download_speed_bps = static_cast<int64_t>(bps);
588 }
589
590 DownloadSource download_source = current_download_source_;
591
592 metrics::DownloadErrorCode payload_download_error_code =
593 metrics::DownloadErrorCode::kUnset;
594 ErrorCode internal_error_code = kErrorCodeSuccess;
595 metrics::AttemptResult attempt_result = utils::GetAttemptResult(code);
596
597 // Add additional detail to AttemptResult
598 switch (attempt_result) {
599 case metrics::AttemptResult::kPayloadDownloadError:
600 payload_download_error_code = utils::GetDownloadErrorCode(code);
601 break;
602
603 case metrics::AttemptResult::kInternalError:
604 internal_error_code = code;
605 break;
606
607 // Explicit fall-through for cases where we do not have additional
608 // detail. We avoid the default keyword to force people adding new
609 // AttemptResult values to visit this code and examine whether
610 // additional detail is needed.
611 case metrics::AttemptResult::kUpdateSucceeded:
612 case metrics::AttemptResult::kMetadataMalformed:
613 case metrics::AttemptResult::kOperationMalformed:
614 case metrics::AttemptResult::kOperationExecutionError:
615 case metrics::AttemptResult::kMetadataVerificationFailed:
616 case metrics::AttemptResult::kPayloadVerificationFailed:
617 case metrics::AttemptResult::kVerificationFailed:
618 case metrics::AttemptResult::kPostInstallFailed:
619 case metrics::AttemptResult::kAbnormalTermination:
620 case metrics::AttemptResult::kNumConstants:
621 case metrics::AttemptResult::kUnset:
622 break;
623 }
624
625 metrics::ReportUpdateAttemptMetrics(system_state_,
626 attempt_number,
627 payload_type,
628 duration,
629 duration_uptime,
630 payload_size,
631 payload_bytes_downloaded,
632 payload_download_speed_bps,
633 download_source,
634 attempt_result,
635 internal_error_code,
David Zeuthenb281f072014-04-02 10:20:19 -0700636 payload_download_error_code,
637 attempt_connection_type_);
David Zeuthen33bae492014-02-25 16:16:18 -0800638}
639
David Zeuthen4e1d1492014-04-25 13:12:27 -0700640void PayloadState::PersistAttemptMetrics() {
641 // TODO(zeuthen): For now we only persist whether an attempt was in
642 // progress and not values/metrics related to the attempt. This
643 // means that when this happens, of all the UpdateEngine.Attempt.*
644 // metrics, only UpdateEngine.Attempt.Result is reported (with the
645 // value |kAbnormalTermination|). In the future we might want to
646 // persist more data so we can report other metrics in the
647 // UpdateEngine.Attempt.* namespace when this happens.
648 prefs_->SetBoolean(kPrefsAttemptInProgress, true);
649}
650
651void PayloadState::ClearPersistedAttemptMetrics() {
652 prefs_->Delete(kPrefsAttemptInProgress);
653}
654
655void PayloadState::ReportAndClearPersistedAttemptMetrics() {
656 bool attempt_in_progress = false;
657 if (!prefs_->GetBoolean(kPrefsAttemptInProgress, &attempt_in_progress))
658 return;
659 if (!attempt_in_progress)
660 return;
661
662 metrics::ReportAbnormallyTerminatedUpdateAttemptMetrics(system_state_);
663
664 ClearPersistedAttemptMetrics();
665}
666
David Zeuthen33bae492014-02-25 16:16:18 -0800667void PayloadState::CollectAndReportSuccessfulUpdateMetrics() {
Jay Srinivasandbd9ea22013-04-22 17:45:19 -0700668 string metric;
David Zeuthen33bae492014-02-25 16:16:18 -0800669
670 // Report metrics collected from all known download sources to UMA.
671 int64_t successful_bytes_by_source[kNumDownloadSources];
672 int64_t total_bytes_by_source[kNumDownloadSources];
673 int64_t successful_bytes = 0;
674 int64_t total_bytes = 0;
675 int64_t successful_mbs = 0;
676 int64_t total_mbs = 0;
677
Jay Srinivasan19409b72013-04-12 19:23:36 -0700678 for (int i = 0; i < kNumDownloadSources; i++) {
679 DownloadSource source = static_cast<DownloadSource>(i);
David Zeuthen33bae492014-02-25 16:16:18 -0800680 int64_t bytes;
Jay Srinivasan19409b72013-04-12 19:23:36 -0700681
David Zeuthen44848602013-06-24 13:32:14 -0700682 // Only consider this download source (and send byte counts) as
683 // having been used if we downloaded a non-trivial amount of bytes
684 // (e.g. at least 1 MiB) that contributed to the final success of
685 // the update. Otherwise we're going to end up with a lot of
686 // zero-byte events in the histogram.
Jay Srinivasandbd9ea22013-04-22 17:45:19 -0700687
David Zeuthen33bae492014-02-25 16:16:18 -0800688 bytes = GetCurrentBytesDownloaded(source);
689 successful_bytes_by_source[i] = bytes;
690 successful_bytes += bytes;
691 successful_mbs += bytes / kNumBytesInOneMiB;
Jay Srinivasan19409b72013-04-12 19:23:36 -0700692 SetCurrentBytesDownloaded(source, 0, true);
693
David Zeuthen33bae492014-02-25 16:16:18 -0800694 bytes = GetTotalBytesDownloaded(source);
695 total_bytes_by_source[i] = bytes;
696 total_bytes += bytes;
697 total_mbs += bytes / kNumBytesInOneMiB;
698 SetTotalBytesDownloaded(source, 0, true);
699 }
700
701 int download_overhead_percentage = 0;
702 if (successful_bytes > 0) {
703 download_overhead_percentage = (total_bytes - successful_bytes) * 100ULL /
704 successful_bytes;
705 }
706
707 int url_switch_count = static_cast<int>(url_switch_count_);
708
709 int reboot_count = GetNumReboots();
710
711 SetNumReboots(0);
712
713 TimeDelta duration = GetUpdateDuration();
714 TimeDelta duration_uptime = GetUpdateDurationUptime();
715
716 prefs_->Delete(kPrefsUpdateTimestampStart);
717 prefs_->Delete(kPrefsUpdateDurationUptime);
718
719 PayloadType payload_type = CalculatePayloadType();
720
721 int64_t payload_size = response_.size;
722
723 int attempt_count = GetPayloadAttemptNumber();
724
725 int updates_abandoned_count = num_responses_seen_ - 1;
726
727 metrics::ReportSuccessfulUpdateMetrics(system_state_,
728 attempt_count,
729 updates_abandoned_count,
730 payload_type,
731 payload_size,
732 total_bytes_by_source,
733 download_overhead_percentage,
734 duration,
735 reboot_count,
736 url_switch_count);
737
738 // TODO(zeuthen): This is the old metric reporting code which is
739 // slated for removal soon. See http://crbug.com/355745 for details.
740
741 // The old metrics code is using MiB's instead of bytes to calculate
742 // the overhead which due to rounding makes the numbers slightly
743 // different.
744 download_overhead_percentage = 0;
745 if (successful_mbs > 0) {
746 download_overhead_percentage = (total_mbs - successful_mbs) * 100ULL /
747 successful_mbs;
748 }
749
750 int download_sources_used = 0;
751 for (int i = 0; i < kNumDownloadSources; i++) {
752 DownloadSource source = static_cast<DownloadSource>(i);
753 const int kMaxMiBs = 10240; // Anything above 10GB goes in the last bucket.
754 int64_t mbs;
755
756 // Only consider this download source (and send byte counts) as
757 // having been used if we downloaded a non-trivial amount of bytes
758 // (e.g. at least 1 MiB) that contributed to the final success of
759 // the update. Otherwise we're going to end up with a lot of
760 // zero-byte events in the histogram.
761
762 mbs = successful_bytes_by_source[i] / kNumBytesInOneMiB;
David Zeuthen44848602013-06-24 13:32:14 -0700763 if (mbs > 0) {
David Zeuthen33bae492014-02-25 16:16:18 -0800764 metric = "Installer.SuccessfulMBsDownloadedFrom" +
765 utils::ToString(source);
David Zeuthen44848602013-06-24 13:32:14 -0700766 LOG(INFO) << "Uploading " << mbs << " (MBs) for metric " << metric;
767 system_state_->metrics_lib()->SendToUMA(metric,
768 mbs,
769 0, // min
770 kMaxMiBs,
771 kNumDefaultUmaBuckets);
772 }
David Zeuthen33bae492014-02-25 16:16:18 -0800773
774 mbs = total_bytes_by_source[i] / kNumBytesInOneMiB;
775 if (mbs > 0) {
776 metric = "Installer.TotalMBsDownloadedFrom" + utils::ToString(source);
777 LOG(INFO) << "Uploading " << mbs << " (MBs) for metric " << metric;
778 system_state_->metrics_lib()->SendToUMA(metric,
779 mbs,
780 0, // min
781 kMaxMiBs,
782 kNumDefaultUmaBuckets);
783 download_sources_used |= (1 << i);
784 }
Jay Srinivasan19409b72013-04-12 19:23:36 -0700785 }
Jay Srinivasandbd9ea22013-04-22 17:45:19 -0700786
787 metric = "Installer.DownloadSourcesUsed";
788 LOG(INFO) << "Uploading 0x" << std::hex << download_sources_used
789 << " (bit flags) for metric " << metric;
790 int num_buckets = std::min(1 << kNumDownloadSources, kNumDefaultUmaBuckets);
791 system_state_->metrics_lib()->SendToUMA(metric,
792 download_sources_used,
793 0, // min
794 1 << kNumDownloadSources,
795 num_buckets);
796
David Zeuthen33bae492014-02-25 16:16:18 -0800797 metric = "Installer.DownloadOverheadPercentage";
798 LOG(INFO) << "Uploading " << download_overhead_percentage
799 << "% for metric " << metric;
800 system_state_->metrics_lib()->SendToUMA(metric,
801 download_overhead_percentage,
802 0, // min: 0% overhead
803 1000, // max: 1000% overhead
804 kNumDefaultUmaBuckets);
Jay Srinivasan19409b72013-04-12 19:23:36 -0700805
David Zeuthen33bae492014-02-25 16:16:18 -0800806 metric = "Installer.UpdateURLSwitches";
807 LOG(INFO) << "Uploading " << url_switch_count
808 << " (count) for metric " << metric;
David Zeuthencc6f9962013-04-18 11:57:24 -0700809 system_state_->metrics_lib()->SendToUMA(
810 metric,
David Zeuthen33bae492014-02-25 16:16:18 -0800811 url_switch_count,
David Zeuthencc6f9962013-04-18 11:57:24 -0700812 0, // min value
813 100, // max value
814 kNumDefaultUmaBuckets);
David Zeuthencc6f9962013-04-18 11:57:24 -0700815
David Zeuthen33bae492014-02-25 16:16:18 -0800816 metric = "Installer.UpdateNumReboots";
817 LOG(INFO) << "Uploading reboot count of " << reboot_count << " for metric "
Chris Sosabe45bef2013-04-09 18:25:12 -0700818 << metric;
819 system_state_->metrics_lib()->SendToUMA(
820 metric,
David Zeuthen33bae492014-02-25 16:16:18 -0800821 reboot_count, // sample
822 0, // min = 0.
823 50, // max
Chris Sosabe45bef2013-04-09 18:25:12 -0700824 25); // buckets
David Zeuthen33bae492014-02-25 16:16:18 -0800825
826 metric = "Installer.UpdateDurationMinutes";
827 system_state_->metrics_lib()->SendToUMA(
828 metric,
829 static_cast<int>(duration.InMinutes()),
830 1, // min: 1 minute
831 365*24*60, // max: 1 year (approx)
832 kNumDefaultUmaBuckets);
833 LOG(INFO) << "Uploading " << utils::FormatTimeDelta(duration)
834 << " for metric " << metric;
835
836 metric = "Installer.UpdateDurationUptimeMinutes";
837 system_state_->metrics_lib()->SendToUMA(
838 metric,
839 static_cast<int>(duration_uptime.InMinutes()),
840 1, // min: 1 minute
841 30*24*60, // max: 1 month (approx)
842 kNumDefaultUmaBuckets);
843 LOG(INFO) << "Uploading " << utils::FormatTimeDelta(duration_uptime)
844 << " for metric " << metric;
845
846 metric = "Installer.PayloadFormat";
847 system_state_->metrics_lib()->SendEnumToUMA(
848 metric,
849 payload_type,
850 kNumPayloadTypes);
851 LOG(INFO) << "Uploading " << utils::ToString(payload_type)
852 << " for metric " << metric;
853
854 metric = "Installer.AttemptsCount.Total";
855 system_state_->metrics_lib()->SendToUMA(
856 metric,
857 attempt_count,
858 1, // min
859 50, // max
860 kNumDefaultUmaBuckets);
861 LOG(INFO) << "Uploading " << attempt_count
862 << " for metric " << metric;
863
864 metric = "Installer.UpdatesAbandonedCount";
865 LOG(INFO) << "Uploading " << updates_abandoned_count
866 << " (count) for metric " << metric;
867 system_state_->metrics_lib()->SendToUMA(
868 metric,
869 updates_abandoned_count,
870 0, // min value
871 100, // max value
872 kNumDefaultUmaBuckets);
Chris Sosabe45bef2013-04-09 18:25:12 -0700873}
874
875void PayloadState::UpdateNumReboots() {
876 // We only update the reboot count when the system has been detected to have
877 // been rebooted.
878 if (!system_state_->system_rebooted()) {
879 return;
880 }
881
882 SetNumReboots(GetNumReboots() + 1);
883}
884
885void PayloadState::SetNumReboots(uint32_t num_reboots) {
886 CHECK(prefs_);
887 num_reboots_ = num_reboots;
888 prefs_->SetInt64(kPrefsNumReboots, num_reboots);
889 LOG(INFO) << "Number of Reboots during current update attempt = "
890 << num_reboots_;
891}
892
Jay Srinivasan08262882012-12-28 19:29:43 -0800893void PayloadState::ResetPersistedState() {
894 SetPayloadAttemptNumber(0);
Alex Deymo820cc702013-06-28 15:43:46 -0700895 SetFullPayloadAttemptNumber(0);
Jay Srinivasan08262882012-12-28 19:29:43 -0800896 SetUrlIndex(0);
897 SetUrlFailureCount(0);
David Zeuthencc6f9962013-04-18 11:57:24 -0700898 SetUrlSwitchCount(0);
Jay Srinivasan08262882012-12-28 19:29:43 -0800899 UpdateBackoffExpiryTime(); // This will reset the backoff expiry time.
David Zeuthenf413fe52013-04-22 14:04:39 -0700900 SetUpdateTimestampStart(system_state_->clock()->GetWallclockTime());
David Zeuthen9a017f22013-04-11 16:10:26 -0700901 SetUpdateTimestampEnd(Time()); // Set to null time
902 SetUpdateDurationUptime(TimeDelta::FromSeconds(0));
Jay Srinivasan19409b72013-04-12 19:23:36 -0700903 ResetDownloadSourcesOnNewUpdate();
Chris Sosaaa18e162013-06-20 13:20:30 -0700904 ResetRollbackVersion();
David Zeuthendcba8092013-08-06 12:16:35 -0700905 SetP2PNumAttempts(0);
906 SetP2PFirstAttemptTimestamp(Time()); // Set to null time
Chris Sosaaa18e162013-06-20 13:20:30 -0700907}
908
909void PayloadState::ResetRollbackVersion() {
910 CHECK(powerwash_safe_prefs_);
911 rollback_version_ = "";
912 powerwash_safe_prefs_->Delete(kPrefsRollbackVersion);
Jay Srinivasan19409b72013-04-12 19:23:36 -0700913}
914
915void PayloadState::ResetDownloadSourcesOnNewUpdate() {
916 for (int i = 0; i < kNumDownloadSources; i++) {
917 DownloadSource source = static_cast<DownloadSource>(i);
918 SetCurrentBytesDownloaded(source, 0, true);
919 // Note: Not resetting the TotalBytesDownloaded as we want that metric
920 // to count the bytes downloaded across various update attempts until
921 // we have successfully applied the update.
922 }
923}
924
Chris Sosab3dcdb32013-09-04 15:22:12 -0700925int64_t PayloadState::GetPersistedValue(const string& key) {
Jay Srinivasan19409b72013-04-12 19:23:36 -0700926 CHECK(prefs_);
Chris Sosab3dcdb32013-09-04 15:22:12 -0700927 if (!prefs_->Exists(key))
Jay Srinivasan19409b72013-04-12 19:23:36 -0700928 return 0;
929
930 int64_t stored_value;
Chris Sosab3dcdb32013-09-04 15:22:12 -0700931 if (!prefs_->GetInt64(key, &stored_value))
Jay Srinivasan19409b72013-04-12 19:23:36 -0700932 return 0;
933
934 if (stored_value < 0) {
935 LOG(ERROR) << key << ": Invalid value (" << stored_value
936 << ") in persisted state. Defaulting to 0";
937 return 0;
938 }
939
940 return stored_value;
Jay Srinivasan08262882012-12-28 19:29:43 -0800941}
942
943string PayloadState::CalculateResponseSignature() {
Alex Vakulenko75039d72014-03-25 12:36:28 -0700944 string response_sign = base::StringPrintf(
945 "NumURLs = %d\n", static_cast<int>(candidate_urls_.size()));
Jay Srinivasan08262882012-12-28 19:29:43 -0800946
Jay Srinivasan53173b92013-05-17 17:13:01 -0700947 for (size_t i = 0; i < candidate_urls_.size(); i++)
Alex Vakulenko75039d72014-03-25 12:36:28 -0700948 response_sign += base::StringPrintf("Candidate Url%d = %s\n",
949 static_cast<int>(i),
950 candidate_urls_[i].c_str());
Jay Srinivasan08262882012-12-28 19:29:43 -0800951
Alex Vakulenko75039d72014-03-25 12:36:28 -0700952 response_sign += base::StringPrintf(
953 "Payload Size = %ju\n"
954 "Payload Sha256 Hash = %s\n"
955 "Metadata Size = %ju\n"
956 "Metadata Signature = %s\n"
957 "Is Delta Payload = %d\n"
958 "Max Failure Count Per Url = %d\n"
959 "Disable Payload Backoff = %d\n",
960 static_cast<uintmax_t>(response_.size),
961 response_.hash.c_str(),
962 static_cast<uintmax_t>(response_.metadata_size),
963 response_.metadata_signature.c_str(),
964 response_.is_delta_payload,
965 response_.max_failure_count_per_url,
966 response_.disable_payload_backoff);
Jay Srinivasan08262882012-12-28 19:29:43 -0800967 return response_sign;
968}
969
970void PayloadState::LoadResponseSignature() {
Jay Srinivasan6f6ea002012-12-14 11:26:28 -0800971 CHECK(prefs_);
972 string stored_value;
Jay Srinivasan08262882012-12-28 19:29:43 -0800973 if (prefs_->Exists(kPrefsCurrentResponseSignature) &&
974 prefs_->GetString(kPrefsCurrentResponseSignature, &stored_value)) {
975 SetResponseSignature(stored_value);
Jay Srinivasan6f6ea002012-12-14 11:26:28 -0800976 }
Jay Srinivasan6f6ea002012-12-14 11:26:28 -0800977}
978
Jay Srinivasan19409b72013-04-12 19:23:36 -0700979void PayloadState::SetResponseSignature(const string& response_signature) {
Jay Srinivasan08262882012-12-28 19:29:43 -0800980 CHECK(prefs_);
981 response_signature_ = response_signature;
982 LOG(INFO) << "Current Response Signature = \n" << response_signature_;
983 prefs_->SetString(kPrefsCurrentResponseSignature, response_signature_);
984}
985
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800986void PayloadState::LoadPayloadAttemptNumber() {
Chris Sosab3dcdb32013-09-04 15:22:12 -0700987 SetPayloadAttemptNumber(GetPersistedValue(kPrefsPayloadAttemptNumber));
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800988}
989
Alex Deymo820cc702013-06-28 15:43:46 -0700990void PayloadState::LoadFullPayloadAttemptNumber() {
Chris Sosab3dcdb32013-09-04 15:22:12 -0700991 SetFullPayloadAttemptNumber(GetPersistedValue(
992 kPrefsFullPayloadAttemptNumber));
Alex Deymo820cc702013-06-28 15:43:46 -0700993}
994
995void PayloadState::SetPayloadAttemptNumber(int payload_attempt_number) {
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -0800996 CHECK(prefs_);
997 payload_attempt_number_ = payload_attempt_number;
998 LOG(INFO) << "Payload Attempt Number = " << payload_attempt_number_;
999 prefs_->SetInt64(kPrefsPayloadAttemptNumber, payload_attempt_number_);
1000}
1001
Alex Deymo820cc702013-06-28 15:43:46 -07001002void PayloadState::SetFullPayloadAttemptNumber(
1003 int full_payload_attempt_number) {
1004 CHECK(prefs_);
1005 full_payload_attempt_number_ = full_payload_attempt_number;
1006 LOG(INFO) << "Full Payload Attempt Number = " << full_payload_attempt_number_;
1007 prefs_->SetInt64(kPrefsFullPayloadAttemptNumber,
1008 full_payload_attempt_number_);
1009}
1010
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -08001011void PayloadState::LoadUrlIndex() {
Chris Sosab3dcdb32013-09-04 15:22:12 -07001012 SetUrlIndex(GetPersistedValue(kPrefsCurrentUrlIndex));
Jay Srinivasan6f6ea002012-12-14 11:26:28 -08001013}
1014
1015void PayloadState::SetUrlIndex(uint32_t url_index) {
1016 CHECK(prefs_);
Jay Srinivasan6f6ea002012-12-14 11:26:28 -08001017 url_index_ = url_index;
1018 LOG(INFO) << "Current URL Index = " << url_index_;
1019 prefs_->SetInt64(kPrefsCurrentUrlIndex, url_index_);
Jay Srinivasan19409b72013-04-12 19:23:36 -07001020
1021 // Also update the download source, which is purely dependent on the
1022 // current URL index alone.
1023 UpdateCurrentDownloadSource();
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -08001024}
1025
David Zeuthencc6f9962013-04-18 11:57:24 -07001026void PayloadState::LoadUrlSwitchCount() {
Chris Sosab3dcdb32013-09-04 15:22:12 -07001027 SetUrlSwitchCount(GetPersistedValue(kPrefsUrlSwitchCount));
David Zeuthencc6f9962013-04-18 11:57:24 -07001028}
1029
1030void PayloadState::SetUrlSwitchCount(uint32_t url_switch_count) {
1031 CHECK(prefs_);
1032 url_switch_count_ = url_switch_count;
1033 LOG(INFO) << "URL Switch Count = " << url_switch_count_;
1034 prefs_->SetInt64(kPrefsUrlSwitchCount, url_switch_count_);
1035}
1036
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -08001037void PayloadState::LoadUrlFailureCount() {
Chris Sosab3dcdb32013-09-04 15:22:12 -07001038 SetUrlFailureCount(GetPersistedValue(kPrefsCurrentUrlFailureCount));
Jay Srinivasan2b5a0f02012-12-19 17:25:56 -08001039}
1040
1041void PayloadState::SetUrlFailureCount(uint32_t url_failure_count) {
1042 CHECK(prefs_);
1043 url_failure_count_ = url_failure_count;
1044 LOG(INFO) << "Current URL (Url" << GetUrlIndex()
1045 << ")'s Failure Count = " << url_failure_count_;
1046 prefs_->SetInt64(kPrefsCurrentUrlFailureCount, url_failure_count_);
Jay Srinivasan6f6ea002012-12-14 11:26:28 -08001047}
1048
Jay Srinivasan08262882012-12-28 19:29:43 -08001049void PayloadState::LoadBackoffExpiryTime() {
1050 CHECK(prefs_);
1051 int64_t stored_value;
1052 if (!prefs_->Exists(kPrefsBackoffExpiryTime))
1053 return;
1054
1055 if (!prefs_->GetInt64(kPrefsBackoffExpiryTime, &stored_value))
1056 return;
1057
1058 Time stored_time = Time::FromInternalValue(stored_value);
1059 if (stored_time > Time::Now() + TimeDelta::FromDays(kMaxBackoffDays)) {
1060 LOG(ERROR) << "Invalid backoff expiry time ("
1061 << utils::ToString(stored_time)
1062 << ") in persisted state. Resetting.";
1063 stored_time = Time();
1064 }
1065 SetBackoffExpiryTime(stored_time);
1066}
1067
1068void PayloadState::SetBackoffExpiryTime(const Time& new_time) {
1069 CHECK(prefs_);
1070 backoff_expiry_time_ = new_time;
1071 LOG(INFO) << "Backoff Expiry Time = "
1072 << utils::ToString(backoff_expiry_time_);
1073 prefs_->SetInt64(kPrefsBackoffExpiryTime,
1074 backoff_expiry_time_.ToInternalValue());
1075}
1076
David Zeuthen9a017f22013-04-11 16:10:26 -07001077TimeDelta PayloadState::GetUpdateDuration() {
David Zeuthenf413fe52013-04-22 14:04:39 -07001078 Time end_time = update_timestamp_end_.is_null()
1079 ? system_state_->clock()->GetWallclockTime() :
1080 update_timestamp_end_;
David Zeuthen9a017f22013-04-11 16:10:26 -07001081 return end_time - update_timestamp_start_;
1082}
1083
1084void PayloadState::LoadUpdateTimestampStart() {
1085 int64_t stored_value;
1086 Time stored_time;
1087
1088 CHECK(prefs_);
1089
David Zeuthenf413fe52013-04-22 14:04:39 -07001090 Time now = system_state_->clock()->GetWallclockTime();
David Zeuthen9a017f22013-04-11 16:10:26 -07001091
1092 if (!prefs_->Exists(kPrefsUpdateTimestampStart)) {
1093 // The preference missing is not unexpected - in that case, just
1094 // use the current time as start time
1095 stored_time = now;
1096 } else if (!prefs_->GetInt64(kPrefsUpdateTimestampStart, &stored_value)) {
1097 LOG(ERROR) << "Invalid UpdateTimestampStart value. Resetting.";
1098 stored_time = now;
1099 } else {
1100 stored_time = Time::FromInternalValue(stored_value);
1101 }
1102
1103 // Sanity check: If the time read from disk is in the future
1104 // (modulo some slack to account for possible NTP drift
1105 // adjustments), something is fishy and we should report and
1106 // reset.
1107 TimeDelta duration_according_to_stored_time = now - stored_time;
1108 if (duration_according_to_stored_time < -kDurationSlack) {
1109 LOG(ERROR) << "The UpdateTimestampStart value ("
1110 << utils::ToString(stored_time)
1111 << ") in persisted state is "
David Zeuthen674c3182013-04-18 14:05:20 -07001112 << utils::FormatTimeDelta(duration_according_to_stored_time)
1113 << " in the future. Resetting.";
David Zeuthen9a017f22013-04-11 16:10:26 -07001114 stored_time = now;
1115 }
1116
1117 SetUpdateTimestampStart(stored_time);
1118}
1119
1120void PayloadState::SetUpdateTimestampStart(const Time& value) {
1121 CHECK(prefs_);
1122 update_timestamp_start_ = value;
1123 prefs_->SetInt64(kPrefsUpdateTimestampStart,
1124 update_timestamp_start_.ToInternalValue());
1125 LOG(INFO) << "Update Timestamp Start = "
1126 << utils::ToString(update_timestamp_start_);
1127}
1128
1129void PayloadState::SetUpdateTimestampEnd(const Time& value) {
1130 update_timestamp_end_ = value;
1131 LOG(INFO) << "Update Timestamp End = "
1132 << utils::ToString(update_timestamp_end_);
1133}
1134
1135TimeDelta PayloadState::GetUpdateDurationUptime() {
1136 return update_duration_uptime_;
1137}
1138
1139void PayloadState::LoadUpdateDurationUptime() {
1140 int64_t stored_value;
1141 TimeDelta stored_delta;
1142
1143 CHECK(prefs_);
1144
1145 if (!prefs_->Exists(kPrefsUpdateDurationUptime)) {
1146 // The preference missing is not unexpected - in that case, just
1147 // we'll use zero as the delta
1148 } else if (!prefs_->GetInt64(kPrefsUpdateDurationUptime, &stored_value)) {
1149 LOG(ERROR) << "Invalid UpdateDurationUptime value. Resetting.";
1150 stored_delta = TimeDelta::FromSeconds(0);
1151 } else {
1152 stored_delta = TimeDelta::FromInternalValue(stored_value);
1153 }
1154
1155 // Sanity-check: Uptime can never be greater than the wall-clock
1156 // difference (modulo some slack). If it is, report and reset
1157 // to the wall-clock difference.
1158 TimeDelta diff = GetUpdateDuration() - stored_delta;
1159 if (diff < -kDurationSlack) {
1160 LOG(ERROR) << "The UpdateDurationUptime value ("
David Zeuthen674c3182013-04-18 14:05:20 -07001161 << utils::FormatTimeDelta(stored_delta)
David Zeuthen9a017f22013-04-11 16:10:26 -07001162 << ") in persisted state is "
David Zeuthen674c3182013-04-18 14:05:20 -07001163 << utils::FormatTimeDelta(diff)
1164 << " larger than the wall-clock delta. Resetting.";
David Zeuthen9a017f22013-04-11 16:10:26 -07001165 stored_delta = update_duration_current_;
1166 }
1167
1168 SetUpdateDurationUptime(stored_delta);
1169}
1170
Chris Sosabe45bef2013-04-09 18:25:12 -07001171void PayloadState::LoadNumReboots() {
Chris Sosab3dcdb32013-09-04 15:22:12 -07001172 SetNumReboots(GetPersistedValue(kPrefsNumReboots));
Chris Sosaaa18e162013-06-20 13:20:30 -07001173}
1174
1175void PayloadState::LoadRollbackVersion() {
Chris Sosab3dcdb32013-09-04 15:22:12 -07001176 CHECK(powerwash_safe_prefs_);
1177 string rollback_version;
1178 if (powerwash_safe_prefs_->GetString(kPrefsRollbackVersion,
1179 &rollback_version)) {
1180 SetRollbackVersion(rollback_version);
1181 }
Chris Sosaaa18e162013-06-20 13:20:30 -07001182}
1183
1184void PayloadState::SetRollbackVersion(const string& rollback_version) {
1185 CHECK(powerwash_safe_prefs_);
1186 LOG(INFO) << "Blacklisting version "<< rollback_version;
1187 rollback_version_ = rollback_version;
1188 powerwash_safe_prefs_->SetString(kPrefsRollbackVersion, rollback_version);
Chris Sosabe45bef2013-04-09 18:25:12 -07001189}
1190
David Zeuthen9a017f22013-04-11 16:10:26 -07001191void PayloadState::SetUpdateDurationUptimeExtended(const TimeDelta& value,
1192 const Time& timestamp,
1193 bool use_logging) {
1194 CHECK(prefs_);
1195 update_duration_uptime_ = value;
1196 update_duration_uptime_timestamp_ = timestamp;
1197 prefs_->SetInt64(kPrefsUpdateDurationUptime,
1198 update_duration_uptime_.ToInternalValue());
1199 if (use_logging) {
1200 LOG(INFO) << "Update Duration Uptime = "
David Zeuthen674c3182013-04-18 14:05:20 -07001201 << utils::FormatTimeDelta(update_duration_uptime_);
David Zeuthen9a017f22013-04-11 16:10:26 -07001202 }
1203}
1204
1205void PayloadState::SetUpdateDurationUptime(const TimeDelta& value) {
David Zeuthenf413fe52013-04-22 14:04:39 -07001206 Time now = system_state_->clock()->GetMonotonicTime();
1207 SetUpdateDurationUptimeExtended(value, now, true);
David Zeuthen9a017f22013-04-11 16:10:26 -07001208}
1209
1210void PayloadState::CalculateUpdateDurationUptime() {
David Zeuthenf413fe52013-04-22 14:04:39 -07001211 Time now = system_state_->clock()->GetMonotonicTime();
David Zeuthen9a017f22013-04-11 16:10:26 -07001212 TimeDelta uptime_since_last_update = now - update_duration_uptime_timestamp_;
1213 TimeDelta new_uptime = update_duration_uptime_ + uptime_since_last_update;
1214 // We're frequently called so avoid logging this write
1215 SetUpdateDurationUptimeExtended(new_uptime, now, false);
1216}
1217
Jay Srinivasan19409b72013-04-12 19:23:36 -07001218string PayloadState::GetPrefsKey(const string& prefix, DownloadSource source) {
1219 return prefix + "-from-" + utils::ToString(source);
1220}
1221
1222void PayloadState::LoadCurrentBytesDownloaded(DownloadSource source) {
1223 string key = GetPrefsKey(kPrefsCurrentBytesDownloaded, source);
Chris Sosab3dcdb32013-09-04 15:22:12 -07001224 SetCurrentBytesDownloaded(source, GetPersistedValue(key), true);
Jay Srinivasan19409b72013-04-12 19:23:36 -07001225}
1226
1227void PayloadState::SetCurrentBytesDownloaded(
1228 DownloadSource source,
1229 uint64_t current_bytes_downloaded,
1230 bool log) {
1231 CHECK(prefs_);
1232
1233 if (source >= kNumDownloadSources)
1234 return;
1235
1236 // Update the in-memory value.
1237 current_bytes_downloaded_[source] = current_bytes_downloaded;
1238
1239 string prefs_key = GetPrefsKey(kPrefsCurrentBytesDownloaded, source);
1240 prefs_->SetInt64(prefs_key, current_bytes_downloaded);
1241 LOG_IF(INFO, log) << "Current bytes downloaded for "
1242 << utils::ToString(source) << " = "
1243 << GetCurrentBytesDownloaded(source);
1244}
1245
1246void PayloadState::LoadTotalBytesDownloaded(DownloadSource source) {
1247 string key = GetPrefsKey(kPrefsTotalBytesDownloaded, source);
Chris Sosab3dcdb32013-09-04 15:22:12 -07001248 SetTotalBytesDownloaded(source, GetPersistedValue(key), true);
Jay Srinivasan19409b72013-04-12 19:23:36 -07001249}
1250
1251void PayloadState::SetTotalBytesDownloaded(
1252 DownloadSource source,
1253 uint64_t total_bytes_downloaded,
1254 bool log) {
1255 CHECK(prefs_);
1256
1257 if (source >= kNumDownloadSources)
1258 return;
1259
1260 // Update the in-memory value.
1261 total_bytes_downloaded_[source] = total_bytes_downloaded;
1262
1263 // Persist.
1264 string prefs_key = GetPrefsKey(kPrefsTotalBytesDownloaded, source);
1265 prefs_->SetInt64(prefs_key, total_bytes_downloaded);
1266 LOG_IF(INFO, log) << "Total bytes downloaded for "
1267 << utils::ToString(source) << " = "
1268 << GetTotalBytesDownloaded(source);
1269}
1270
David Zeuthena573d6f2013-06-14 16:13:36 -07001271void PayloadState::LoadNumResponsesSeen() {
Chris Sosab3dcdb32013-09-04 15:22:12 -07001272 SetNumResponsesSeen(GetPersistedValue(kPrefsNumResponsesSeen));
David Zeuthena573d6f2013-06-14 16:13:36 -07001273}
1274
1275void PayloadState::SetNumResponsesSeen(int num_responses_seen) {
1276 CHECK(prefs_);
1277 num_responses_seen_ = num_responses_seen;
1278 LOG(INFO) << "Num Responses Seen = " << num_responses_seen_;
1279 prefs_->SetInt64(kPrefsNumResponsesSeen, num_responses_seen_);
1280}
1281
Alex Deymob33b0f02013-08-08 21:10:02 -07001282void PayloadState::ReportUpdatesAbandonedEventCountMetric() {
1283 string metric = "Installer.UpdatesAbandonedEventCount";
1284 int value = num_responses_seen_ - 1;
1285
1286 // Do not send an "abandoned" event when 0 payloads were abandoned since the
1287 // last successful update.
1288 if (value == 0)
1289 return;
1290
1291 LOG(INFO) << "Uploading " << value << " (count) for metric " << metric;
1292 system_state_->metrics_lib()->SendToUMA(
1293 metric,
1294 value,
1295 0, // min value
1296 100, // max value
1297 kNumDefaultUmaBuckets);
1298}
1299
Jay Srinivasan53173b92013-05-17 17:13:01 -07001300void PayloadState::ComputeCandidateUrls() {
Chris Sosaf7d80042013-08-22 16:45:17 -07001301 bool http_url_ok = true;
Jay Srinivasan53173b92013-05-17 17:13:01 -07001302
J. Richard Barnette056b0ab2013-10-29 15:24:56 -07001303 if (system_state_->hardware()->IsOfficialBuild()) {
Jay Srinivasan53173b92013-05-17 17:13:01 -07001304 const policy::DevicePolicy* policy = system_state_->device_policy();
Chris Sosaf7d80042013-08-22 16:45:17 -07001305 if (policy && policy->GetHttpDownloadsEnabled(&http_url_ok) && !http_url_ok)
Jay Srinivasan53173b92013-05-17 17:13:01 -07001306 LOG(INFO) << "Downloads via HTTP Url are not enabled by device policy";
1307 } else {
1308 LOG(INFO) << "Allowing HTTP downloads for unofficial builds";
1309 http_url_ok = true;
1310 }
1311
1312 candidate_urls_.clear();
1313 for (size_t i = 0; i < response_.payload_urls.size(); i++) {
1314 string candidate_url = response_.payload_urls[i];
1315 if (StartsWithASCII(candidate_url, "http://", false) && !http_url_ok)
1316 continue;
1317 candidate_urls_.push_back(candidate_url);
1318 LOG(INFO) << "Candidate Url" << (candidate_urls_.size() - 1)
1319 << ": " << candidate_url;
1320 }
1321
1322 LOG(INFO) << "Found " << candidate_urls_.size() << " candidate URLs "
1323 << "out of " << response_.payload_urls.size() << " URLs supplied";
1324}
1325
David Zeuthene4c58bf2013-06-18 17:26:50 -07001326void PayloadState::CreateSystemUpdatedMarkerFile() {
1327 CHECK(prefs_);
1328 int64_t value = system_state_->clock()->GetWallclockTime().ToInternalValue();
1329 prefs_->SetInt64(kPrefsSystemUpdatedMarker, value);
1330}
1331
1332void PayloadState::BootedIntoUpdate(TimeDelta time_to_reboot) {
1333 // Send |time_to_reboot| as a UMA stat.
1334 string metric = "Installer.TimeToRebootMinutes";
1335 system_state_->metrics_lib()->SendToUMA(metric,
1336 time_to_reboot.InMinutes(),
1337 0, // min: 0 minute
1338 30*24*60, // max: 1 month (approx)
1339 kNumDefaultUmaBuckets);
1340 LOG(INFO) << "Uploading " << utils::FormatTimeDelta(time_to_reboot)
1341 << " for metric " << metric;
David Zeuthen33bae492014-02-25 16:16:18 -08001342
1343 metric = metrics::kMetricTimeToRebootMinutes;
1344 system_state_->metrics_lib()->SendToUMA(metric,
1345 time_to_reboot.InMinutes(),
1346 0, // min: 0 minute
1347 30*24*60, // max: 1 month (approx)
1348 kNumDefaultUmaBuckets);
1349 LOG(INFO) << "Uploading " << utils::FormatTimeDelta(time_to_reboot)
1350 << " for metric " << metric;
David Zeuthene4c58bf2013-06-18 17:26:50 -07001351}
1352
1353void PayloadState::UpdateEngineStarted() {
David Zeuthen4e1d1492014-04-25 13:12:27 -07001354 // Flush previous state from abnormal attempt failure, if any.
1355 ReportAndClearPersistedAttemptMetrics();
1356
Alex Deymo569c4242013-07-24 12:01:01 -07001357 // Avoid the UpdateEngineStarted actions if this is not the first time we
1358 // run the update engine since reboot.
1359 if (!system_state_->system_rebooted())
1360 return;
1361
David Zeuthene4c58bf2013-06-18 17:26:50 -07001362 // Figure out if we just booted into a new update
1363 if (prefs_->Exists(kPrefsSystemUpdatedMarker)) {
1364 int64_t stored_value;
1365 if (prefs_->GetInt64(kPrefsSystemUpdatedMarker, &stored_value)) {
1366 Time system_updated_at = Time::FromInternalValue(stored_value);
1367 if (!system_updated_at.is_null()) {
1368 TimeDelta time_to_reboot =
1369 system_state_->clock()->GetWallclockTime() - system_updated_at;
1370 if (time_to_reboot.ToInternalValue() < 0) {
1371 LOG(ERROR) << "time_to_reboot is negative - system_updated_at: "
1372 << utils::ToString(system_updated_at);
1373 } else {
1374 BootedIntoUpdate(time_to_reboot);
1375 }
1376 }
1377 }
1378 prefs_->Delete(kPrefsSystemUpdatedMarker);
1379 }
Alex Deymo42432912013-07-12 20:21:15 -07001380 // Check if it is needed to send metrics about a failed reboot into a new
1381 // version.
1382 ReportFailedBootIfNeeded();
1383}
1384
1385void PayloadState::ReportFailedBootIfNeeded() {
1386 // If the kPrefsTargetVersionInstalledFrom is present, a successfully applied
1387 // payload was marked as ready immediately before the last reboot, and we
1388 // need to check if such payload successfully rebooted or not.
1389 if (prefs_->Exists(kPrefsTargetVersionInstalledFrom)) {
Alex Vakulenko4f5b1442014-02-21 12:19:44 -08001390 int64_t installed_from = 0;
1391 if (!prefs_->GetInt64(kPrefsTargetVersionInstalledFrom, &installed_from)) {
Alex Deymo42432912013-07-12 20:21:15 -07001392 LOG(ERROR) << "Error reading TargetVersionInstalledFrom on reboot.";
1393 return;
1394 }
Alex Vakulenko4f5b1442014-02-21 12:19:44 -08001395 if (int(installed_from) ==
1396 utils::GetPartitionNumber(system_state_->hardware()->BootDevice())) {
Alex Deymo42432912013-07-12 20:21:15 -07001397 // A reboot was pending, but the chromebook is again in the same
1398 // BootDevice where the update was installed from.
1399 int64_t target_attempt;
1400 if (!prefs_->GetInt64(kPrefsTargetVersionAttempt, &target_attempt)) {
1401 LOG(ERROR) << "Error reading TargetVersionAttempt when "
1402 "TargetVersionInstalledFrom was present.";
1403 target_attempt = 1;
1404 }
1405
1406 // Report the UMA metric of the current boot failure.
1407 string metric = "Installer.RebootToNewPartitionAttempt";
1408
1409 LOG(INFO) << "Uploading " << target_attempt
1410 << " (count) for metric " << metric;
1411 system_state_->metrics_lib()->SendToUMA(
1412 metric,
1413 target_attempt,
1414 1, // min value
1415 50, // max value
1416 kNumDefaultUmaBuckets);
David Zeuthen33bae492014-02-25 16:16:18 -08001417
1418 metric = metrics::kMetricFailedUpdateCount;
1419 LOG(INFO) << "Uploading " << target_attempt
1420 << " (count) for metric " << metric;
1421 system_state_->metrics_lib()->SendToUMA(
1422 metric,
1423 target_attempt,
1424 1, // min value
1425 50, // max value
1426 kNumDefaultUmaBuckets);
Alex Deymo42432912013-07-12 20:21:15 -07001427 } else {
1428 prefs_->Delete(kPrefsTargetVersionAttempt);
1429 prefs_->Delete(kPrefsTargetVersionUniqueId);
1430 }
1431 prefs_->Delete(kPrefsTargetVersionInstalledFrom);
1432 }
1433}
1434
1435void PayloadState::ExpectRebootInNewVersion(const string& target_version_uid) {
1436 // Expect to boot into the new partition in the next reboot setting the
1437 // TargetVersion* flags in the Prefs.
1438 string stored_target_version_uid;
1439 string target_version_id;
1440 string target_partition;
1441 int64_t target_attempt;
1442
1443 if (prefs_->Exists(kPrefsTargetVersionUniqueId) &&
1444 prefs_->GetString(kPrefsTargetVersionUniqueId,
1445 &stored_target_version_uid) &&
1446 stored_target_version_uid == target_version_uid) {
1447 if (!prefs_->GetInt64(kPrefsTargetVersionAttempt, &target_attempt))
1448 target_attempt = 0;
1449 } else {
1450 prefs_->SetString(kPrefsTargetVersionUniqueId, target_version_uid);
1451 target_attempt = 0;
1452 }
1453 prefs_->SetInt64(kPrefsTargetVersionAttempt, target_attempt + 1);
1454
Alex Vakulenko4f5b1442014-02-21 12:19:44 -08001455 prefs_->SetInt64(kPrefsTargetVersionInstalledFrom,
1456 utils::GetPartitionNumber(
Alex Deymo42432912013-07-12 20:21:15 -07001457 system_state_->hardware()->BootDevice()));
1458}
1459
1460void PayloadState::ResetUpdateStatus() {
1461 // Remove the TargetVersionInstalledFrom pref so that if the machine is
1462 // rebooted the next boot is not flagged as failed to rebooted into the
1463 // new applied payload.
1464 prefs_->Delete(kPrefsTargetVersionInstalledFrom);
1465
1466 // Also decrement the attempt number if it exists.
1467 int64_t target_attempt;
1468 if (prefs_->GetInt64(kPrefsTargetVersionAttempt, &target_attempt))
1469 prefs_->SetInt64(kPrefsTargetVersionAttempt, target_attempt-1);
David Zeuthene4c58bf2013-06-18 17:26:50 -07001470}
1471
David Zeuthendcba8092013-08-06 12:16:35 -07001472int PayloadState::GetP2PNumAttempts() {
1473 return p2p_num_attempts_;
1474}
1475
1476void PayloadState::SetP2PNumAttempts(int value) {
1477 p2p_num_attempts_ = value;
1478 LOG(INFO) << "p2p Num Attempts = " << p2p_num_attempts_;
1479 CHECK(prefs_);
1480 prefs_->SetInt64(kPrefsP2PNumAttempts, value);
1481}
1482
1483void PayloadState::LoadP2PNumAttempts() {
Chris Sosab3dcdb32013-09-04 15:22:12 -07001484 SetP2PNumAttempts(GetPersistedValue(kPrefsP2PNumAttempts));
David Zeuthendcba8092013-08-06 12:16:35 -07001485}
1486
1487Time PayloadState::GetP2PFirstAttemptTimestamp() {
1488 return p2p_first_attempt_timestamp_;
1489}
1490
1491void PayloadState::SetP2PFirstAttemptTimestamp(const Time& time) {
1492 p2p_first_attempt_timestamp_ = time;
1493 LOG(INFO) << "p2p First Attempt Timestamp = "
1494 << utils::ToString(p2p_first_attempt_timestamp_);
1495 CHECK(prefs_);
1496 int64_t stored_value = time.ToInternalValue();
1497 prefs_->SetInt64(kPrefsP2PFirstAttemptTimestamp, stored_value);
1498}
1499
1500void PayloadState::LoadP2PFirstAttemptTimestamp() {
Chris Sosab3dcdb32013-09-04 15:22:12 -07001501 int64_t stored_value = GetPersistedValue(kPrefsP2PFirstAttemptTimestamp);
David Zeuthendcba8092013-08-06 12:16:35 -07001502 Time stored_time = Time::FromInternalValue(stored_value);
1503 SetP2PFirstAttemptTimestamp(stored_time);
1504}
1505
1506void PayloadState::P2PNewAttempt() {
1507 CHECK(prefs_);
1508 // Set timestamp, if it hasn't been set already
1509 if (p2p_first_attempt_timestamp_.is_null()) {
1510 SetP2PFirstAttemptTimestamp(system_state_->clock()->GetWallclockTime());
1511 }
1512 // Increase number of attempts
1513 SetP2PNumAttempts(GetP2PNumAttempts() + 1);
1514}
1515
1516bool PayloadState::P2PAttemptAllowed() {
1517 if (p2p_num_attempts_ > kMaxP2PAttempts) {
1518 LOG(INFO) << "Number of p2p attempts is " << p2p_num_attempts_
1519 << " which is greater than "
1520 << kMaxP2PAttempts
1521 << " - disallowing p2p.";
1522 return false;
1523 }
1524
1525 if (!p2p_first_attempt_timestamp_.is_null()) {
1526 Time now = system_state_->clock()->GetWallclockTime();
1527 TimeDelta time_spent_attempting_p2p = now - p2p_first_attempt_timestamp_;
1528 if (time_spent_attempting_p2p.InSeconds() < 0) {
1529 LOG(ERROR) << "Time spent attempting p2p is negative"
1530 << " - disallowing p2p.";
1531 return false;
1532 }
1533 if (time_spent_attempting_p2p.InSeconds() > kMaxP2PAttemptTimeSeconds) {
1534 LOG(INFO) << "Time spent attempting p2p is "
1535 << utils::FormatTimeDelta(time_spent_attempting_p2p)
1536 << " which is greater than "
1537 << utils::FormatTimeDelta(TimeDelta::FromSeconds(
1538 kMaxP2PAttemptTimeSeconds))
1539 << " - disallowing p2p.";
1540 return false;
1541 }
1542 }
1543
1544 return true;
1545}
1546
Jay Srinivasan6f6ea002012-12-14 11:26:28 -08001547} // namespace chromeos_update_engine