1 // 2 // Copyright (C) 2012 The Android Open Source Project 3 // 4 // Licensed under the Apache License, Version 2.0 (the "License"); 5 // you may not use this file except in compliance with the License. 6 // You may obtain a copy of the License at 7 // 8 // http://www.apache.org/licenses/LICENSE-2.0 9 // 10 // Unless required by applicable law or agreed to in writing, software 11 // distributed under the License is distributed on an "AS IS" BASIS, 12 // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 // See the License for the specific language governing permissions and 14 // limitations under the License. 15 // 16 17 #include "update_engine/payload_state.h" 18 19 #include <algorithm> 20 #include <string> 21 22 #include <base/logging.h> 23 #include <base/strings/string_util.h> 24 #include <base/strings/stringprintf.h> 25 #include <metrics/metrics_library.h> 26 #include <policy/device_policy.h> 27 28 #include "update_engine/common/clock.h" 29 #include "update_engine/common/constants.h" 30 #include "update_engine/common/error_code_utils.h" 31 #include "update_engine/common/hardware_interface.h" 32 #include "update_engine/common/prefs.h" 33 #include "update_engine/common/utils.h" 34 #include "update_engine/metrics_utils.h" 35 #include "update_engine/omaha_request_params.h" 36 #include "update_engine/payload_consumer/install_plan.h" 37 #include "update_engine/system_state.h" 38 39 using base::Time; 40 using base::TimeDelta; 41 using std::min; 42 using std::string; 43 44 namespace chromeos_update_engine { 45 46 const TimeDelta PayloadState::kDurationSlack = TimeDelta::FromSeconds(600); 47 48 // We want to upperbound backoffs to 16 days 49 static const int kMaxBackoffDays = 16; 50 51 // We want to randomize retry attempts after the backoff by +/- 6 hours. 52 static const uint32_t kMaxBackoffFuzzMinutes = 12 * 60; 53 54 PayloadState::PayloadState() 55 : prefs_(nullptr), 56 using_p2p_for_downloading_(false), 57 p2p_num_attempts_(0), 58 payload_attempt_number_(0), 59 full_payload_attempt_number_(0), 60 url_index_(0), 61 url_failure_count_(0), 62 url_switch_count_(0), 63 attempt_num_bytes_downloaded_(0), 64 attempt_connection_type_(metrics::ConnectionType::kUnknown), 65 attempt_error_code_(ErrorCode::kSuccess), 66 attempt_type_(AttemptType::kUpdate) { 67 for (int i = 0; i <= kNumDownloadSources; i++) 68 total_bytes_downloaded_[i] = current_bytes_downloaded_[i] = 0; 69 } 70 71 bool PayloadState::Initialize(SystemState* system_state) { 72 system_state_ = system_state; 73 prefs_ = system_state_->prefs(); 74 powerwash_safe_prefs_ = system_state_->powerwash_safe_prefs(); 75 LoadResponseSignature(); 76 LoadPayloadAttemptNumber(); 77 LoadFullPayloadAttemptNumber(); 78 LoadUrlIndex(); 79 LoadUrlFailureCount(); 80 LoadUrlSwitchCount(); 81 LoadBackoffExpiryTime(); 82 LoadUpdateTimestampStart(); 83 // The LoadUpdateDurationUptime() method relies on LoadUpdateTimestampStart() 84 // being called before it. Don't reorder. 85 LoadUpdateDurationUptime(); 86 for (int i = 0; i < kNumDownloadSources; i++) { 87 DownloadSource source = static_cast<DownloadSource>(i); 88 LoadCurrentBytesDownloaded(source); 89 LoadTotalBytesDownloaded(source); 90 } 91 LoadNumReboots(); 92 LoadNumResponsesSeen(); 93 LoadRollbackVersion(); 94 LoadP2PFirstAttemptTimestamp(); 95 LoadP2PNumAttempts(); 96 return true; 97 } 98 99 void PayloadState::SetResponse(const OmahaResponse& omaha_response) { 100 // Always store the latest response. 101 response_ = omaha_response; 102 103 // Compute the candidate URLs first as they are used to calculate the 104 // response signature so that a change in enterprise policy for 105 // HTTP downloads being enabled or not could be honored as soon as the 106 // next update check happens. 107 ComputeCandidateUrls(); 108 109 // Check if the "signature" of this response (i.e. the fields we care about) 110 // has changed. 111 string new_response_signature = CalculateResponseSignature(); 112 bool has_response_changed = (response_signature_ != new_response_signature); 113 114 // If the response has changed, we should persist the new signature and 115 // clear away all the existing state. 116 if (has_response_changed) { 117 LOG(INFO) << "Resetting all persisted state as this is a new response"; 118 SetNumResponsesSeen(num_responses_seen_ + 1); 119 SetResponseSignature(new_response_signature); 120 ResetPersistedState(); 121 return; 122 } 123 124 // This is the earliest point at which we can validate whether the URL index 125 // we loaded from the persisted state is a valid value. If the response 126 // hasn't changed but the URL index is invalid, it's indicative of some 127 // tampering of the persisted state. 128 if (static_cast<uint32_t>(url_index_) >= candidate_urls_.size()) { 129 LOG(INFO) << "Resetting all payload state as the url index seems to have " 130 "been tampered with"; 131 ResetPersistedState(); 132 return; 133 } 134 135 // Update the current download source which depends on the latest value of 136 // the response. 137 UpdateCurrentDownloadSource(); 138 } 139 140 void PayloadState::SetUsingP2PForDownloading(bool value) { 141 using_p2p_for_downloading_ = value; 142 // Update the current download source which depends on whether we are 143 // using p2p or not. 144 UpdateCurrentDownloadSource(); 145 } 146 147 void PayloadState::DownloadComplete() { 148 LOG(INFO) << "Payload downloaded successfully"; 149 IncrementPayloadAttemptNumber(); 150 IncrementFullPayloadAttemptNumber(); 151 } 152 153 void PayloadState::DownloadProgress(size_t count) { 154 if (count == 0) 155 return; 156 157 CalculateUpdateDurationUptime(); 158 UpdateBytesDownloaded(count); 159 160 // We've received non-zero bytes from a recent download operation. Since our 161 // URL failure count is meant to penalize a URL only for consecutive 162 // failures, downloading bytes successfully means we should reset the failure 163 // count (as we know at least that the URL is working). In future, we can 164 // design this to be more sophisticated to check for more intelligent failure 165 // patterns, but right now, even 1 byte downloaded will mark the URL to be 166 // good unless it hits 10 (or configured number of) consecutive failures 167 // again. 168 169 if (GetUrlFailureCount() == 0) 170 return; 171 172 LOG(INFO) << "Resetting failure count of Url" << GetUrlIndex() 173 << " to 0 as we received " << count << " bytes successfully"; 174 SetUrlFailureCount(0); 175 } 176 177 void PayloadState::AttemptStarted(AttemptType attempt_type) { 178 // Flush previous state from abnormal attempt failure, if any. 179 ReportAndClearPersistedAttemptMetrics(); 180 181 attempt_type_ = attempt_type; 182 183 ClockInterface *clock = system_state_->clock(); 184 attempt_start_time_boot_ = clock->GetBootTime(); 185 attempt_start_time_monotonic_ = clock->GetMonotonicTime(); 186 attempt_num_bytes_downloaded_ = 0; 187 188 metrics::ConnectionType type; 189 NetworkConnectionType network_connection_type; 190 NetworkTethering tethering; 191 ConnectionManagerInterface* connection_manager = 192 system_state_->connection_manager(); 193 if (!connection_manager->GetConnectionProperties(&network_connection_type, 194 &tethering)) { 195 LOG(ERROR) << "Failed to determine connection type."; 196 type = metrics::ConnectionType::kUnknown; 197 } else { 198 type = metrics_utils::GetConnectionType(network_connection_type, tethering); 199 } 200 attempt_connection_type_ = type; 201 202 if (attempt_type == AttemptType::kUpdate) 203 PersistAttemptMetrics(); 204 } 205 206 void PayloadState::UpdateResumed() { 207 LOG(INFO) << "Resuming an update that was previously started."; 208 UpdateNumReboots(); 209 AttemptStarted(AttemptType::kUpdate); 210 } 211 212 void PayloadState::UpdateRestarted() { 213 LOG(INFO) << "Starting a new update"; 214 ResetDownloadSourcesOnNewUpdate(); 215 SetNumReboots(0); 216 AttemptStarted(AttemptType::kUpdate); 217 } 218 219 void PayloadState::UpdateSucceeded() { 220 // Send the relevant metrics that are tracked in this class to UMA. 221 CalculateUpdateDurationUptime(); 222 SetUpdateTimestampEnd(system_state_->clock()->GetWallclockTime()); 223 224 switch (attempt_type_) { 225 case AttemptType::kUpdate: 226 CollectAndReportAttemptMetrics(ErrorCode::kSuccess); 227 CollectAndReportSuccessfulUpdateMetrics(); 228 ClearPersistedAttemptMetrics(); 229 break; 230 231 case AttemptType::kRollback: 232 metrics::ReportRollbackMetrics(system_state_, 233 metrics::RollbackResult::kSuccess); 234 break; 235 } 236 attempt_error_code_ = ErrorCode::kSuccess; 237 238 // Reset the number of responses seen since it counts from the last 239 // successful update, e.g. now. 240 SetNumResponsesSeen(0); 241 242 CreateSystemUpdatedMarkerFile(); 243 } 244 245 void PayloadState::UpdateFailed(ErrorCode error) { 246 ErrorCode base_error = utils::GetBaseErrorCode(error); 247 LOG(INFO) << "Updating payload state for error code: " << base_error 248 << " (" << utils::ErrorCodeToString(base_error) << ")"; 249 250 if (candidate_urls_.size() == 0) { 251 // This means we got this error even before we got a valid Omaha response 252 // or don't have any valid candidates in the Omaha response. 253 // So we should not advance the url_index_ in such cases. 254 LOG(INFO) << "Ignoring failures until we get a valid Omaha response."; 255 return; 256 } 257 258 switch (attempt_type_) { 259 case AttemptType::kUpdate: 260 CollectAndReportAttemptMetrics(base_error); 261 ClearPersistedAttemptMetrics(); 262 break; 263 264 case AttemptType::kRollback: 265 metrics::ReportRollbackMetrics(system_state_, 266 metrics::RollbackResult::kFailed); 267 break; 268 } 269 270 attempt_error_code_ = base_error; 271 272 switch (base_error) { 273 // Errors which are good indicators of a problem with a particular URL or 274 // the protocol used in the URL or entities in the communication channel 275 // (e.g. proxies). We should try the next available URL in the next update 276 // check to quickly recover from these errors. 277 case ErrorCode::kPayloadHashMismatchError: 278 case ErrorCode::kPayloadSizeMismatchError: 279 case ErrorCode::kDownloadPayloadVerificationError: 280 case ErrorCode::kDownloadPayloadPubKeyVerificationError: 281 case ErrorCode::kSignedDeltaPayloadExpectedError: 282 case ErrorCode::kDownloadInvalidMetadataMagicString: 283 case ErrorCode::kDownloadSignatureMissingInManifest: 284 case ErrorCode::kDownloadManifestParseError: 285 case ErrorCode::kDownloadMetadataSignatureError: 286 case ErrorCode::kDownloadMetadataSignatureVerificationError: 287 case ErrorCode::kDownloadMetadataSignatureMismatch: 288 case ErrorCode::kDownloadOperationHashVerificationError: 289 case ErrorCode::kDownloadOperationExecutionError: 290 case ErrorCode::kDownloadOperationHashMismatch: 291 case ErrorCode::kDownloadInvalidMetadataSize: 292 case ErrorCode::kDownloadInvalidMetadataSignature: 293 case ErrorCode::kDownloadOperationHashMissingError: 294 case ErrorCode::kDownloadMetadataSignatureMissingError: 295 case ErrorCode::kPayloadMismatchedType: 296 case ErrorCode::kUnsupportedMajorPayloadVersion: 297 case ErrorCode::kUnsupportedMinorPayloadVersion: 298 IncrementUrlIndex(); 299 break; 300 301 // Errors which seem to be just transient network/communication related 302 // failures and do not indicate any inherent problem with the URL itself. 303 // So, we should keep the current URL but just increment the 304 // failure count to give it more chances. This way, while we maximize our 305 // chances of downloading from the URLs that appear earlier in the response 306 // (because download from a local server URL that appears earlier in a 307 // response is preferable than downloading from the next URL which could be 308 // a internet URL and thus could be more expensive). 309 310 case ErrorCode::kError: 311 case ErrorCode::kDownloadTransferError: 312 case ErrorCode::kDownloadWriteError: 313 case ErrorCode::kDownloadStateInitializationError: 314 case ErrorCode::kOmahaErrorInHTTPResponse: // Aggregate for HTTP errors. 315 IncrementFailureCount(); 316 break; 317 318 // Errors which are not specific to a URL and hence shouldn't result in 319 // the URL being penalized. This can happen in two cases: 320 // 1. We haven't started downloading anything: These errors don't cost us 321 // anything in terms of actual payload bytes, so we should just do the 322 // regular retries at the next update check. 323 // 2. We have successfully downloaded the payload: In this case, the 324 // payload attempt number would have been incremented and would take care 325 // of the backoff at the next update check. 326 // In either case, there's no need to update URL index or failure count. 327 case ErrorCode::kOmahaRequestError: 328 case ErrorCode::kOmahaResponseHandlerError: 329 case ErrorCode::kPostinstallRunnerError: 330 case ErrorCode::kFilesystemCopierError: 331 case ErrorCode::kInstallDeviceOpenError: 332 case ErrorCode::kKernelDeviceOpenError: 333 case ErrorCode::kDownloadNewPartitionInfoError: 334 case ErrorCode::kNewRootfsVerificationError: 335 case ErrorCode::kNewKernelVerificationError: 336 case ErrorCode::kPostinstallBootedFromFirmwareB: 337 case ErrorCode::kPostinstallFirmwareRONotUpdatable: 338 case ErrorCode::kOmahaRequestEmptyResponseError: 339 case ErrorCode::kOmahaRequestXMLParseError: 340 case ErrorCode::kOmahaResponseInvalid: 341 case ErrorCode::kOmahaUpdateIgnoredPerPolicy: 342 case ErrorCode::kOmahaUpdateDeferredPerPolicy: 343 case ErrorCode::kOmahaUpdateDeferredForBackoff: 344 case ErrorCode::kPostinstallPowerwashError: 345 case ErrorCode::kUpdateCanceledByChannelChange: 346 case ErrorCode::kOmahaRequestXMLHasEntityDecl: 347 case ErrorCode::kFilesystemVerifierError: 348 case ErrorCode::kUserCanceled: 349 LOG(INFO) << "Not incrementing URL index or failure count for this error"; 350 break; 351 352 case ErrorCode::kSuccess: // success code 353 case ErrorCode::kUmaReportedMax: // not an error code 354 case ErrorCode::kOmahaRequestHTTPResponseBase: // aggregated already 355 case ErrorCode::kDevModeFlag: // not an error code 356 case ErrorCode::kResumedFlag: // not an error code 357 case ErrorCode::kTestImageFlag: // not an error code 358 case ErrorCode::kTestOmahaUrlFlag: // not an error code 359 case ErrorCode::kSpecialFlags: // not an error code 360 // These shouldn't happen. Enumerating these explicitly here so that we 361 // can let the compiler warn about new error codes that are added to 362 // action_processor.h but not added here. 363 LOG(WARNING) << "Unexpected error code for UpdateFailed"; 364 break; 365 366 // Note: Not adding a default here so as to let the compiler warn us of 367 // any new enums that were added in the .h but not listed in this switch. 368 } 369 } 370 371 bool PayloadState::ShouldBackoffDownload() { 372 if (response_.disable_payload_backoff) { 373 LOG(INFO) << "Payload backoff logic is disabled. " 374 "Can proceed with the download"; 375 return false; 376 } 377 if (GetUsingP2PForDownloading() && !GetP2PUrl().empty()) { 378 LOG(INFO) << "Payload backoff logic is disabled because download " 379 << "will happen from local peer (via p2p)."; 380 return false; 381 } 382 if (system_state_->request_params()->interactive()) { 383 LOG(INFO) << "Payload backoff disabled for interactive update checks."; 384 return false; 385 } 386 if (response_.is_delta_payload) { 387 // If delta payloads fail, we want to fallback quickly to full payloads as 388 // they are more likely to succeed. Exponential backoffs would greatly 389 // slow down the fallback to full payloads. So we don't backoff for delta 390 // payloads. 391 LOG(INFO) << "No backoffs for delta payloads. " 392 << "Can proceed with the download"; 393 return false; 394 } 395 396 if (!system_state_->hardware()->IsOfficialBuild()) { 397 // Backoffs are needed only for official builds. We do not want any delays 398 // or update failures due to backoffs during testing or development. 399 LOG(INFO) << "No backoffs for test/dev images. " 400 << "Can proceed with the download"; 401 return false; 402 } 403 404 if (backoff_expiry_time_.is_null()) { 405 LOG(INFO) << "No backoff expiry time has been set. " 406 << "Can proceed with the download"; 407 return false; 408 } 409 410 if (backoff_expiry_time_ < Time::Now()) { 411 LOG(INFO) << "The backoff expiry time (" 412 << utils::ToString(backoff_expiry_time_) 413 << ") has elapsed. Can proceed with the download"; 414 return false; 415 } 416 417 LOG(INFO) << "Cannot proceed with downloads as we need to backoff until " 418 << utils::ToString(backoff_expiry_time_); 419 return true; 420 } 421 422 void PayloadState::Rollback() { 423 SetRollbackVersion(system_state_->request_params()->app_version()); 424 AttemptStarted(AttemptType::kRollback); 425 } 426 427 void PayloadState::IncrementPayloadAttemptNumber() { 428 // Update the payload attempt number for both payload types: full and delta. 429 SetPayloadAttemptNumber(GetPayloadAttemptNumber() + 1); 430 } 431 432 void PayloadState::IncrementFullPayloadAttemptNumber() { 433 // Update the payload attempt number for full payloads and the backoff time. 434 if (response_.is_delta_payload) { 435 LOG(INFO) << "Not incrementing payload attempt number for delta payloads"; 436 return; 437 } 438 439 LOG(INFO) << "Incrementing the full payload attempt number"; 440 SetFullPayloadAttemptNumber(GetFullPayloadAttemptNumber() + 1); 441 UpdateBackoffExpiryTime(); 442 } 443 444 void PayloadState::IncrementUrlIndex() { 445 uint32_t next_url_index = GetUrlIndex() + 1; 446 if (next_url_index < candidate_urls_.size()) { 447 LOG(INFO) << "Incrementing the URL index for next attempt"; 448 SetUrlIndex(next_url_index); 449 } else { 450 LOG(INFO) << "Resetting the current URL index (" << GetUrlIndex() << ") to " 451 << "0 as we only have " << candidate_urls_.size() 452 << " candidate URL(s)"; 453 SetUrlIndex(0); 454 IncrementPayloadAttemptNumber(); 455 IncrementFullPayloadAttemptNumber(); 456 } 457 458 // If we have multiple URLs, record that we just switched to another one 459 if (candidate_urls_.size() > 1) 460 SetUrlSwitchCount(url_switch_count_ + 1); 461 462 // Whenever we update the URL index, we should also clear the URL failure 463 // count so we can start over fresh for the new URL. 464 SetUrlFailureCount(0); 465 } 466 467 void PayloadState::IncrementFailureCount() { 468 uint32_t next_url_failure_count = GetUrlFailureCount() + 1; 469 if (next_url_failure_count < response_.max_failure_count_per_url) { 470 LOG(INFO) << "Incrementing the URL failure count"; 471 SetUrlFailureCount(next_url_failure_count); 472 } else { 473 LOG(INFO) << "Reached max number of failures for Url" << GetUrlIndex() 474 << ". Trying next available URL"; 475 IncrementUrlIndex(); 476 } 477 } 478 479 void PayloadState::UpdateBackoffExpiryTime() { 480 if (response_.disable_payload_backoff) { 481 LOG(INFO) << "Resetting backoff expiry time as payload backoff is disabled"; 482 SetBackoffExpiryTime(Time()); 483 return; 484 } 485 486 if (GetFullPayloadAttemptNumber() == 0) { 487 SetBackoffExpiryTime(Time()); 488 return; 489 } 490 491 // Since we're doing left-shift below, make sure we don't shift more 492 // than this. E.g. if int is 4-bytes, don't left-shift more than 30 bits, 493 // since we don't expect value of kMaxBackoffDays to be more than 100 anyway. 494 int num_days = 1; // the value to be shifted. 495 const int kMaxShifts = (sizeof(num_days) * 8) - 2; 496 497 // Normal backoff days is 2 raised to (payload_attempt_number - 1). 498 // E.g. if payload_attempt_number is over 30, limit power to 30. 499 int power = min(GetFullPayloadAttemptNumber() - 1, kMaxShifts); 500 501 // The number of days is the minimum of 2 raised to (payload_attempt_number 502 // - 1) or kMaxBackoffDays. 503 num_days = min(num_days << power, kMaxBackoffDays); 504 505 // We don't want all retries to happen exactly at the same time when 506 // retrying after backoff. So add some random minutes to fuzz. 507 int fuzz_minutes = utils::FuzzInt(0, kMaxBackoffFuzzMinutes); 508 TimeDelta next_backoff_interval = TimeDelta::FromDays(num_days) + 509 TimeDelta::FromMinutes(fuzz_minutes); 510 LOG(INFO) << "Incrementing the backoff expiry time by " 511 << utils::FormatTimeDelta(next_backoff_interval); 512 SetBackoffExpiryTime(Time::Now() + next_backoff_interval); 513 } 514 515 void PayloadState::UpdateCurrentDownloadSource() { 516 current_download_source_ = kNumDownloadSources; 517 518 if (using_p2p_for_downloading_) { 519 current_download_source_ = kDownloadSourceHttpPeer; 520 } else if (GetUrlIndex() < candidate_urls_.size()) { 521 string current_url = candidate_urls_[GetUrlIndex()]; 522 if (base::StartsWith(current_url, "https://", 523 base::CompareCase::INSENSITIVE_ASCII)) { 524 current_download_source_ = kDownloadSourceHttpsServer; 525 } else if (base::StartsWith(current_url, "http://", 526 base::CompareCase::INSENSITIVE_ASCII)) { 527 current_download_source_ = kDownloadSourceHttpServer; 528 } 529 } 530 531 LOG(INFO) << "Current download source: " 532 << utils::ToString(current_download_source_); 533 } 534 535 void PayloadState::UpdateBytesDownloaded(size_t count) { 536 SetCurrentBytesDownloaded( 537 current_download_source_, 538 GetCurrentBytesDownloaded(current_download_source_) + count, 539 false); 540 SetTotalBytesDownloaded( 541 current_download_source_, 542 GetTotalBytesDownloaded(current_download_source_) + count, 543 false); 544 545 attempt_num_bytes_downloaded_ += count; 546 } 547 548 PayloadType PayloadState::CalculatePayloadType() { 549 PayloadType payload_type; 550 OmahaRequestParams* params = system_state_->request_params(); 551 if (response_.is_delta_payload) { 552 payload_type = kPayloadTypeDelta; 553 } else if (params->delta_okay()) { 554 payload_type = kPayloadTypeFull; 555 } else { // Full payload, delta was not allowed by request. 556 payload_type = kPayloadTypeForcedFull; 557 } 558 return payload_type; 559 } 560 561 // TODO(zeuthen): Currently we don't report the UpdateEngine.Attempt.* 562 // metrics if the attempt ends abnormally, e.g. if the update_engine 563 // process crashes or the device is rebooted. See 564 // http://crbug.com/357676 565 void PayloadState::CollectAndReportAttemptMetrics(ErrorCode code) { 566 int attempt_number = GetPayloadAttemptNumber(); 567 568 PayloadType payload_type = CalculatePayloadType(); 569 570 int64_t payload_size = response_.size; 571 572 int64_t payload_bytes_downloaded = attempt_num_bytes_downloaded_; 573 574 ClockInterface *clock = system_state_->clock(); 575 TimeDelta duration = clock->GetBootTime() - attempt_start_time_boot_; 576 TimeDelta duration_uptime = clock->GetMonotonicTime() - 577 attempt_start_time_monotonic_; 578 579 int64_t payload_download_speed_bps = 0; 580 int64_t usec = duration_uptime.InMicroseconds(); 581 if (usec > 0) { 582 double sec = static_cast<double>(usec) / Time::kMicrosecondsPerSecond; 583 double bps = static_cast<double>(payload_bytes_downloaded) / sec; 584 payload_download_speed_bps = static_cast<int64_t>(bps); 585 } 586 587 DownloadSource download_source = current_download_source_; 588 589 metrics::DownloadErrorCode payload_download_error_code = 590 metrics::DownloadErrorCode::kUnset; 591 ErrorCode internal_error_code = ErrorCode::kSuccess; 592 metrics::AttemptResult attempt_result = metrics_utils::GetAttemptResult(code); 593 594 // Add additional detail to AttemptResult 595 switch (attempt_result) { 596 case metrics::AttemptResult::kPayloadDownloadError: 597 payload_download_error_code = metrics_utils::GetDownloadErrorCode(code); 598 break; 599 600 case metrics::AttemptResult::kInternalError: 601 internal_error_code = code; 602 break; 603 604 // Explicit fall-through for cases where we do not have additional 605 // detail. We avoid the default keyword to force people adding new 606 // AttemptResult values to visit this code and examine whether 607 // additional detail is needed. 608 case metrics::AttemptResult::kUpdateSucceeded: 609 case metrics::AttemptResult::kMetadataMalformed: 610 case metrics::AttemptResult::kOperationMalformed: 611 case metrics::AttemptResult::kOperationExecutionError: 612 case metrics::AttemptResult::kMetadataVerificationFailed: 613 case metrics::AttemptResult::kPayloadVerificationFailed: 614 case metrics::AttemptResult::kVerificationFailed: 615 case metrics::AttemptResult::kPostInstallFailed: 616 case metrics::AttemptResult::kAbnormalTermination: 617 case metrics::AttemptResult::kUpdateCanceled: 618 case metrics::AttemptResult::kNumConstants: 619 case metrics::AttemptResult::kUnset: 620 break; 621 } 622 623 metrics::ReportUpdateAttemptMetrics(system_state_, 624 attempt_number, 625 payload_type, 626 duration, 627 duration_uptime, 628 payload_size, 629 payload_bytes_downloaded, 630 payload_download_speed_bps, 631 download_source, 632 attempt_result, 633 internal_error_code, 634 payload_download_error_code, 635 attempt_connection_type_); 636 } 637 638 void PayloadState::PersistAttemptMetrics() { 639 // TODO(zeuthen): For now we only persist whether an attempt was in 640 // progress and not values/metrics related to the attempt. This 641 // means that when this happens, of all the UpdateEngine.Attempt.* 642 // metrics, only UpdateEngine.Attempt.Result is reported (with the 643 // value |kAbnormalTermination|). In the future we might want to 644 // persist more data so we can report other metrics in the 645 // UpdateEngine.Attempt.* namespace when this happens. 646 prefs_->SetBoolean(kPrefsAttemptInProgress, true); 647 } 648 649 void PayloadState::ClearPersistedAttemptMetrics() { 650 prefs_->Delete(kPrefsAttemptInProgress); 651 } 652 653 void PayloadState::ReportAndClearPersistedAttemptMetrics() { 654 bool attempt_in_progress = false; 655 if (!prefs_->GetBoolean(kPrefsAttemptInProgress, &attempt_in_progress)) 656 return; 657 if (!attempt_in_progress) 658 return; 659 660 metrics::ReportAbnormallyTerminatedUpdateAttemptMetrics(system_state_); 661 662 ClearPersistedAttemptMetrics(); 663 } 664 665 void PayloadState::CollectAndReportSuccessfulUpdateMetrics() { 666 string metric; 667 668 // Report metrics collected from all known download sources to UMA. 669 int64_t total_bytes_by_source[kNumDownloadSources]; 670 int64_t successful_bytes = 0; 671 int64_t total_bytes = 0; 672 int64_t successful_mbs = 0; 673 int64_t total_mbs = 0; 674 675 for (int i = 0; i < kNumDownloadSources; i++) { 676 DownloadSource source = static_cast<DownloadSource>(i); 677 int64_t bytes; 678 679 // Only consider this download source (and send byte counts) as 680 // having been used if we downloaded a non-trivial amount of bytes 681 // (e.g. at least 1 MiB) that contributed to the final success of 682 // the update. Otherwise we're going to end up with a lot of 683 // zero-byte events in the histogram. 684 685 bytes = GetCurrentBytesDownloaded(source); 686 successful_bytes += bytes; 687 successful_mbs += bytes / kNumBytesInOneMiB; 688 SetCurrentBytesDownloaded(source, 0, true); 689 690 bytes = GetTotalBytesDownloaded(source); 691 total_bytes_by_source[i] = bytes; 692 total_bytes += bytes; 693 total_mbs += bytes / kNumBytesInOneMiB; 694 SetTotalBytesDownloaded(source, 0, true); 695 } 696 697 int download_overhead_percentage = 0; 698 if (successful_bytes > 0) { 699 download_overhead_percentage = (total_bytes - successful_bytes) * 100ULL / 700 successful_bytes; 701 } 702 703 int url_switch_count = static_cast<int>(url_switch_count_); 704 705 int reboot_count = GetNumReboots(); 706 707 SetNumReboots(0); 708 709 TimeDelta duration = GetUpdateDuration(); 710 711 prefs_->Delete(kPrefsUpdateTimestampStart); 712 prefs_->Delete(kPrefsUpdateDurationUptime); 713 714 PayloadType payload_type = CalculatePayloadType(); 715 716 int64_t payload_size = response_.size; 717 718 int attempt_count = GetPayloadAttemptNumber(); 719 720 int updates_abandoned_count = num_responses_seen_ - 1; 721 722 metrics::ReportSuccessfulUpdateMetrics(system_state_, 723 attempt_count, 724 updates_abandoned_count, 725 payload_type, 726 payload_size, 727 total_bytes_by_source, 728 download_overhead_percentage, 729 duration, 730 reboot_count, 731 url_switch_count); 732 } 733 734 void PayloadState::UpdateNumReboots() { 735 // We only update the reboot count when the system has been detected to have 736 // been rebooted. 737 if (!system_state_->system_rebooted()) { 738 return; 739 } 740 741 SetNumReboots(GetNumReboots() + 1); 742 } 743 744 void PayloadState::SetNumReboots(uint32_t num_reboots) { 745 CHECK(prefs_); 746 num_reboots_ = num_reboots; 747 prefs_->SetInt64(kPrefsNumReboots, num_reboots); 748 LOG(INFO) << "Number of Reboots during current update attempt = " 749 << num_reboots_; 750 } 751 752 void PayloadState::ResetPersistedState() { 753 SetPayloadAttemptNumber(0); 754 SetFullPayloadAttemptNumber(0); 755 SetUrlIndex(0); 756 SetUrlFailureCount(0); 757 SetUrlSwitchCount(0); 758 UpdateBackoffExpiryTime(); // This will reset the backoff expiry time. 759 SetUpdateTimestampStart(system_state_->clock()->GetWallclockTime()); 760 SetUpdateTimestampEnd(Time()); // Set to null time 761 SetUpdateDurationUptime(TimeDelta::FromSeconds(0)); 762 ResetDownloadSourcesOnNewUpdate(); 763 ResetRollbackVersion(); 764 SetP2PNumAttempts(0); 765 SetP2PFirstAttemptTimestamp(Time()); // Set to null time 766 SetScatteringWaitPeriod(TimeDelta()); 767 } 768 769 void PayloadState::ResetRollbackVersion() { 770 CHECK(powerwash_safe_prefs_); 771 rollback_version_ = ""; 772 powerwash_safe_prefs_->Delete(kPrefsRollbackVersion); 773 } 774 775 void PayloadState::ResetDownloadSourcesOnNewUpdate() { 776 for (int i = 0; i < kNumDownloadSources; i++) { 777 DownloadSource source = static_cast<DownloadSource>(i); 778 SetCurrentBytesDownloaded(source, 0, true); 779 // Note: Not resetting the TotalBytesDownloaded as we want that metric 780 // to count the bytes downloaded across various update attempts until 781 // we have successfully applied the update. 782 } 783 } 784 785 int64_t PayloadState::GetPersistedValue(const string& key) { 786 CHECK(prefs_); 787 if (!prefs_->Exists(key)) 788 return 0; 789 790 int64_t stored_value; 791 if (!prefs_->GetInt64(key, &stored_value)) 792 return 0; 793 794 if (stored_value < 0) { 795 LOG(ERROR) << key << ": Invalid value (" << stored_value 796 << ") in persisted state. Defaulting to 0"; 797 return 0; 798 } 799 800 return stored_value; 801 } 802 803 string PayloadState::CalculateResponseSignature() { 804 string response_sign = base::StringPrintf( 805 "NumURLs = %d\n", static_cast<int>(candidate_urls_.size())); 806 807 for (size_t i = 0; i < candidate_urls_.size(); i++) 808 response_sign += base::StringPrintf("Candidate Url%d = %s\n", 809 static_cast<int>(i), 810 candidate_urls_[i].c_str()); 811 812 response_sign += base::StringPrintf( 813 "Payload Size = %ju\n" 814 "Payload Sha256 Hash = %s\n" 815 "Metadata Size = %ju\n" 816 "Metadata Signature = %s\n" 817 "Is Delta Payload = %d\n" 818 "Max Failure Count Per Url = %d\n" 819 "Disable Payload Backoff = %d\n", 820 static_cast<uintmax_t>(response_.size), 821 response_.hash.c_str(), 822 static_cast<uintmax_t>(response_.metadata_size), 823 response_.metadata_signature.c_str(), 824 response_.is_delta_payload, 825 response_.max_failure_count_per_url, 826 response_.disable_payload_backoff); 827 return response_sign; 828 } 829 830 void PayloadState::LoadResponseSignature() { 831 CHECK(prefs_); 832 string stored_value; 833 if (prefs_->Exists(kPrefsCurrentResponseSignature) && 834 prefs_->GetString(kPrefsCurrentResponseSignature, &stored_value)) { 835 SetResponseSignature(stored_value); 836 } 837 } 838 839 void PayloadState::SetResponseSignature(const string& response_signature) { 840 CHECK(prefs_); 841 response_signature_ = response_signature; 842 LOG(INFO) << "Current Response Signature = \n" << response_signature_; 843 prefs_->SetString(kPrefsCurrentResponseSignature, response_signature_); 844 } 845 846 void PayloadState::LoadPayloadAttemptNumber() { 847 SetPayloadAttemptNumber(GetPersistedValue(kPrefsPayloadAttemptNumber)); 848 } 849 850 void PayloadState::LoadFullPayloadAttemptNumber() { 851 SetFullPayloadAttemptNumber(GetPersistedValue( 852 kPrefsFullPayloadAttemptNumber)); 853 } 854 855 void PayloadState::SetPayloadAttemptNumber(int payload_attempt_number) { 856 CHECK(prefs_); 857 payload_attempt_number_ = payload_attempt_number; 858 LOG(INFO) << "Payload Attempt Number = " << payload_attempt_number_; 859 prefs_->SetInt64(kPrefsPayloadAttemptNumber, payload_attempt_number_); 860 } 861 862 void PayloadState::SetFullPayloadAttemptNumber( 863 int full_payload_attempt_number) { 864 CHECK(prefs_); 865 full_payload_attempt_number_ = full_payload_attempt_number; 866 LOG(INFO) << "Full Payload Attempt Number = " << full_payload_attempt_number_; 867 prefs_->SetInt64(kPrefsFullPayloadAttemptNumber, 868 full_payload_attempt_number_); 869 } 870 871 void PayloadState::LoadUrlIndex() { 872 SetUrlIndex(GetPersistedValue(kPrefsCurrentUrlIndex)); 873 } 874 875 void PayloadState::SetUrlIndex(uint32_t url_index) { 876 CHECK(prefs_); 877 url_index_ = url_index; 878 LOG(INFO) << "Current URL Index = " << url_index_; 879 prefs_->SetInt64(kPrefsCurrentUrlIndex, url_index_); 880 881 // Also update the download source, which is purely dependent on the 882 // current URL index alone. 883 UpdateCurrentDownloadSource(); 884 } 885 886 void PayloadState::LoadScatteringWaitPeriod() { 887 SetScatteringWaitPeriod( 888 TimeDelta::FromSeconds(GetPersistedValue(kPrefsWallClockWaitPeriod))); 889 } 890 891 void PayloadState::SetScatteringWaitPeriod(TimeDelta wait_period) { 892 CHECK(prefs_); 893 scattering_wait_period_ = wait_period; 894 LOG(INFO) << "Scattering Wait Period (seconds) = " 895 << scattering_wait_period_.InSeconds(); 896 if (scattering_wait_period_.InSeconds() > 0) { 897 prefs_->SetInt64(kPrefsWallClockWaitPeriod, 898 scattering_wait_period_.InSeconds()); 899 } else { 900 prefs_->Delete(kPrefsWallClockWaitPeriod); 901 } 902 } 903 904 void PayloadState::LoadUrlSwitchCount() { 905 SetUrlSwitchCount(GetPersistedValue(kPrefsUrlSwitchCount)); 906 } 907 908 void PayloadState::SetUrlSwitchCount(uint32_t url_switch_count) { 909 CHECK(prefs_); 910 url_switch_count_ = url_switch_count; 911 LOG(INFO) << "URL Switch Count = " << url_switch_count_; 912 prefs_->SetInt64(kPrefsUrlSwitchCount, url_switch_count_); 913 } 914 915 void PayloadState::LoadUrlFailureCount() { 916 SetUrlFailureCount(GetPersistedValue(kPrefsCurrentUrlFailureCount)); 917 } 918 919 void PayloadState::SetUrlFailureCount(uint32_t url_failure_count) { 920 CHECK(prefs_); 921 url_failure_count_ = url_failure_count; 922 LOG(INFO) << "Current URL (Url" << GetUrlIndex() 923 << ")'s Failure Count = " << url_failure_count_; 924 prefs_->SetInt64(kPrefsCurrentUrlFailureCount, url_failure_count_); 925 } 926 927 void PayloadState::LoadBackoffExpiryTime() { 928 CHECK(prefs_); 929 int64_t stored_value; 930 if (!prefs_->Exists(kPrefsBackoffExpiryTime)) 931 return; 932 933 if (!prefs_->GetInt64(kPrefsBackoffExpiryTime, &stored_value)) 934 return; 935 936 Time stored_time = Time::FromInternalValue(stored_value); 937 if (stored_time > Time::Now() + TimeDelta::FromDays(kMaxBackoffDays)) { 938 LOG(ERROR) << "Invalid backoff expiry time (" 939 << utils::ToString(stored_time) 940 << ") in persisted state. Resetting."; 941 stored_time = Time(); 942 } 943 SetBackoffExpiryTime(stored_time); 944 } 945 946 void PayloadState::SetBackoffExpiryTime(const Time& new_time) { 947 CHECK(prefs_); 948 backoff_expiry_time_ = new_time; 949 LOG(INFO) << "Backoff Expiry Time = " 950 << utils::ToString(backoff_expiry_time_); 951 prefs_->SetInt64(kPrefsBackoffExpiryTime, 952 backoff_expiry_time_.ToInternalValue()); 953 } 954 955 TimeDelta PayloadState::GetUpdateDuration() { 956 Time end_time = update_timestamp_end_.is_null() 957 ? system_state_->clock()->GetWallclockTime() : 958 update_timestamp_end_; 959 return end_time - update_timestamp_start_; 960 } 961 962 void PayloadState::LoadUpdateTimestampStart() { 963 int64_t stored_value; 964 Time stored_time; 965 966 CHECK(prefs_); 967 968 Time now = system_state_->clock()->GetWallclockTime(); 969 970 if (!prefs_->Exists(kPrefsUpdateTimestampStart)) { 971 // The preference missing is not unexpected - in that case, just 972 // use the current time as start time 973 stored_time = now; 974 } else if (!prefs_->GetInt64(kPrefsUpdateTimestampStart, &stored_value)) { 975 LOG(ERROR) << "Invalid UpdateTimestampStart value. Resetting."; 976 stored_time = now; 977 } else { 978 stored_time = Time::FromInternalValue(stored_value); 979 } 980 981 // Sanity check: If the time read from disk is in the future 982 // (modulo some slack to account for possible NTP drift 983 // adjustments), something is fishy and we should report and 984 // reset. 985 TimeDelta duration_according_to_stored_time = now - stored_time; 986 if (duration_according_to_stored_time < -kDurationSlack) { 987 LOG(ERROR) << "The UpdateTimestampStart value (" 988 << utils::ToString(stored_time) 989 << ") in persisted state is " 990 << utils::FormatTimeDelta(duration_according_to_stored_time) 991 << " in the future. Resetting."; 992 stored_time = now; 993 } 994 995 SetUpdateTimestampStart(stored_time); 996 } 997 998 void PayloadState::SetUpdateTimestampStart(const Time& value) { 999 CHECK(prefs_); 1000 update_timestamp_start_ = value; 1001 prefs_->SetInt64(kPrefsUpdateTimestampStart, 1002 update_timestamp_start_.ToInternalValue()); 1003 LOG(INFO) << "Update Timestamp Start = " 1004 << utils::ToString(update_timestamp_start_); 1005 } 1006 1007 void PayloadState::SetUpdateTimestampEnd(const Time& value) { 1008 update_timestamp_end_ = value; 1009 LOG(INFO) << "Update Timestamp End = " 1010 << utils::ToString(update_timestamp_end_); 1011 } 1012 1013 TimeDelta PayloadState::GetUpdateDurationUptime() { 1014 return update_duration_uptime_; 1015 } 1016 1017 void PayloadState::LoadUpdateDurationUptime() { 1018 int64_t stored_value; 1019 TimeDelta stored_delta; 1020 1021 CHECK(prefs_); 1022 1023 if (!prefs_->Exists(kPrefsUpdateDurationUptime)) { 1024 // The preference missing is not unexpected - in that case, just 1025 // we'll use zero as the delta 1026 } else if (!prefs_->GetInt64(kPrefsUpdateDurationUptime, &stored_value)) { 1027 LOG(ERROR) << "Invalid UpdateDurationUptime value. Resetting."; 1028 stored_delta = TimeDelta::FromSeconds(0); 1029 } else { 1030 stored_delta = TimeDelta::FromInternalValue(stored_value); 1031 } 1032 1033 // Sanity-check: Uptime can never be greater than the wall-clock 1034 // difference (modulo some slack). If it is, report and reset 1035 // to the wall-clock difference. 1036 TimeDelta diff = GetUpdateDuration() - stored_delta; 1037 if (diff < -kDurationSlack) { 1038 LOG(ERROR) << "The UpdateDurationUptime value (" 1039 << utils::FormatTimeDelta(stored_delta) 1040 << ") in persisted state is " 1041 << utils::FormatTimeDelta(diff) 1042 << " larger than the wall-clock delta. Resetting."; 1043 stored_delta = update_duration_current_; 1044 } 1045 1046 SetUpdateDurationUptime(stored_delta); 1047 } 1048 1049 void PayloadState::LoadNumReboots() { 1050 SetNumReboots(GetPersistedValue(kPrefsNumReboots)); 1051 } 1052 1053 void PayloadState::LoadRollbackVersion() { 1054 CHECK(powerwash_safe_prefs_); 1055 string rollback_version; 1056 if (powerwash_safe_prefs_->GetString(kPrefsRollbackVersion, 1057 &rollback_version)) { 1058 SetRollbackVersion(rollback_version); 1059 } 1060 } 1061 1062 void PayloadState::SetRollbackVersion(const string& rollback_version) { 1063 CHECK(powerwash_safe_prefs_); 1064 LOG(INFO) << "Blacklisting version "<< rollback_version; 1065 rollback_version_ = rollback_version; 1066 powerwash_safe_prefs_->SetString(kPrefsRollbackVersion, rollback_version); 1067 } 1068 1069 void PayloadState::SetUpdateDurationUptimeExtended(const TimeDelta& value, 1070 const Time& timestamp, 1071 bool use_logging) { 1072 CHECK(prefs_); 1073 update_duration_uptime_ = value; 1074 update_duration_uptime_timestamp_ = timestamp; 1075 prefs_->SetInt64(kPrefsUpdateDurationUptime, 1076 update_duration_uptime_.ToInternalValue()); 1077 if (use_logging) { 1078 LOG(INFO) << "Update Duration Uptime = " 1079 << utils::FormatTimeDelta(update_duration_uptime_); 1080 } 1081 } 1082 1083 void PayloadState::SetUpdateDurationUptime(const TimeDelta& value) { 1084 Time now = system_state_->clock()->GetMonotonicTime(); 1085 SetUpdateDurationUptimeExtended(value, now, true); 1086 } 1087 1088 void PayloadState::CalculateUpdateDurationUptime() { 1089 Time now = system_state_->clock()->GetMonotonicTime(); 1090 TimeDelta uptime_since_last_update = now - update_duration_uptime_timestamp_; 1091 TimeDelta new_uptime = update_duration_uptime_ + uptime_since_last_update; 1092 // We're frequently called so avoid logging this write 1093 SetUpdateDurationUptimeExtended(new_uptime, now, false); 1094 } 1095 1096 string PayloadState::GetPrefsKey(const string& prefix, DownloadSource source) { 1097 return prefix + "-from-" + utils::ToString(source); 1098 } 1099 1100 void PayloadState::LoadCurrentBytesDownloaded(DownloadSource source) { 1101 string key = GetPrefsKey(kPrefsCurrentBytesDownloaded, source); 1102 SetCurrentBytesDownloaded(source, GetPersistedValue(key), true); 1103 } 1104 1105 void PayloadState::SetCurrentBytesDownloaded( 1106 DownloadSource source, 1107 uint64_t current_bytes_downloaded, 1108 bool log) { 1109 CHECK(prefs_); 1110 1111 if (source >= kNumDownloadSources) 1112 return; 1113 1114 // Update the in-memory value. 1115 current_bytes_downloaded_[source] = current_bytes_downloaded; 1116 1117 string prefs_key = GetPrefsKey(kPrefsCurrentBytesDownloaded, source); 1118 prefs_->SetInt64(prefs_key, current_bytes_downloaded); 1119 LOG_IF(INFO, log) << "Current bytes downloaded for " 1120 << utils::ToString(source) << " = " 1121 << GetCurrentBytesDownloaded(source); 1122 } 1123 1124 void PayloadState::LoadTotalBytesDownloaded(DownloadSource source) { 1125 string key = GetPrefsKey(kPrefsTotalBytesDownloaded, source); 1126 SetTotalBytesDownloaded(source, GetPersistedValue(key), true); 1127 } 1128 1129 void PayloadState::SetTotalBytesDownloaded( 1130 DownloadSource source, 1131 uint64_t total_bytes_downloaded, 1132 bool log) { 1133 CHECK(prefs_); 1134 1135 if (source >= kNumDownloadSources) 1136 return; 1137 1138 // Update the in-memory value. 1139 total_bytes_downloaded_[source] = total_bytes_downloaded; 1140 1141 // Persist. 1142 string prefs_key = GetPrefsKey(kPrefsTotalBytesDownloaded, source); 1143 prefs_->SetInt64(prefs_key, total_bytes_downloaded); 1144 LOG_IF(INFO, log) << "Total bytes downloaded for " 1145 << utils::ToString(source) << " = " 1146 << GetTotalBytesDownloaded(source); 1147 } 1148 1149 void PayloadState::LoadNumResponsesSeen() { 1150 SetNumResponsesSeen(GetPersistedValue(kPrefsNumResponsesSeen)); 1151 } 1152 1153 void PayloadState::SetNumResponsesSeen(int num_responses_seen) { 1154 CHECK(prefs_); 1155 num_responses_seen_ = num_responses_seen; 1156 LOG(INFO) << "Num Responses Seen = " << num_responses_seen_; 1157 prefs_->SetInt64(kPrefsNumResponsesSeen, num_responses_seen_); 1158 } 1159 1160 void PayloadState::ComputeCandidateUrls() { 1161 bool http_url_ok = true; 1162 1163 if (system_state_->hardware()->IsOfficialBuild()) { 1164 const policy::DevicePolicy* policy = system_state_->device_policy(); 1165 if (policy && policy->GetHttpDownloadsEnabled(&http_url_ok) && !http_url_ok) 1166 LOG(INFO) << "Downloads via HTTP Url are not enabled by device policy"; 1167 } else { 1168 LOG(INFO) << "Allowing HTTP downloads for unofficial builds"; 1169 http_url_ok = true; 1170 } 1171 1172 candidate_urls_.clear(); 1173 for (size_t i = 0; i < response_.payload_urls.size(); i++) { 1174 string candidate_url = response_.payload_urls[i]; 1175 if (base::StartsWith(candidate_url, "http://", 1176 base::CompareCase::INSENSITIVE_ASCII) && 1177 !http_url_ok) { 1178 continue; 1179 } 1180 candidate_urls_.push_back(candidate_url); 1181 LOG(INFO) << "Candidate Url" << (candidate_urls_.size() - 1) 1182 << ": " << candidate_url; 1183 } 1184 1185 LOG(INFO) << "Found " << candidate_urls_.size() << " candidate URLs " 1186 << "out of " << response_.payload_urls.size() << " URLs supplied"; 1187 } 1188 1189 void PayloadState::CreateSystemUpdatedMarkerFile() { 1190 CHECK(prefs_); 1191 int64_t value = system_state_->clock()->GetWallclockTime().ToInternalValue(); 1192 prefs_->SetInt64(kPrefsSystemUpdatedMarker, value); 1193 } 1194 1195 void PayloadState::BootedIntoUpdate(TimeDelta time_to_reboot) { 1196 // Send |time_to_reboot| as a UMA stat. 1197 string metric = metrics::kMetricTimeToRebootMinutes; 1198 system_state_->metrics_lib()->SendToUMA(metric, 1199 time_to_reboot.InMinutes(), 1200 0, // min: 0 minute 1201 30*24*60, // max: 1 month (approx) 1202 kNumDefaultUmaBuckets); 1203 LOG(INFO) << "Uploading " << utils::FormatTimeDelta(time_to_reboot) 1204 << " for metric " << metric; 1205 } 1206 1207 void PayloadState::UpdateEngineStarted() { 1208 // Flush previous state from abnormal attempt failure, if any. 1209 ReportAndClearPersistedAttemptMetrics(); 1210 1211 // Avoid the UpdateEngineStarted actions if this is not the first time we 1212 // run the update engine since reboot. 1213 if (!system_state_->system_rebooted()) 1214 return; 1215 1216 // Figure out if we just booted into a new update 1217 if (prefs_->Exists(kPrefsSystemUpdatedMarker)) { 1218 int64_t stored_value; 1219 if (prefs_->GetInt64(kPrefsSystemUpdatedMarker, &stored_value)) { 1220 Time system_updated_at = Time::FromInternalValue(stored_value); 1221 if (!system_updated_at.is_null()) { 1222 TimeDelta time_to_reboot = 1223 system_state_->clock()->GetWallclockTime() - system_updated_at; 1224 if (time_to_reboot.ToInternalValue() < 0) { 1225 LOG(ERROR) << "time_to_reboot is negative - system_updated_at: " 1226 << utils::ToString(system_updated_at); 1227 } else { 1228 BootedIntoUpdate(time_to_reboot); 1229 } 1230 } 1231 } 1232 prefs_->Delete(kPrefsSystemUpdatedMarker); 1233 } 1234 // Check if it is needed to send metrics about a failed reboot into a new 1235 // version. 1236 ReportFailedBootIfNeeded(); 1237 } 1238 1239 void PayloadState::ReportFailedBootIfNeeded() { 1240 // If the kPrefsTargetVersionInstalledFrom is present, a successfully applied 1241 // payload was marked as ready immediately before the last reboot, and we 1242 // need to check if such payload successfully rebooted or not. 1243 if (prefs_->Exists(kPrefsTargetVersionInstalledFrom)) { 1244 int64_t installed_from = 0; 1245 if (!prefs_->GetInt64(kPrefsTargetVersionInstalledFrom, &installed_from)) { 1246 LOG(ERROR) << "Error reading TargetVersionInstalledFrom on reboot."; 1247 return; 1248 } 1249 // Old Chrome OS devices will write 2 or 4 in this setting, with the 1250 // partition number. We are now using slot numbers (0 or 1) instead, so 1251 // the following comparison will not match if we are comparing an old 1252 // partition number against a new slot number, which is the correct outcome 1253 // since we successfully booted the new update in that case. If the boot 1254 // failed, we will read this value from the same version, so it will always 1255 // be compatible. 1256 if (installed_from == system_state_->boot_control()->GetCurrentSlot()) { 1257 // A reboot was pending, but the chromebook is again in the same 1258 // BootDevice where the update was installed from. 1259 int64_t target_attempt; 1260 if (!prefs_->GetInt64(kPrefsTargetVersionAttempt, &target_attempt)) { 1261 LOG(ERROR) << "Error reading TargetVersionAttempt when " 1262 "TargetVersionInstalledFrom was present."; 1263 target_attempt = 1; 1264 } 1265 1266 // Report the UMA metric of the current boot failure. 1267 string metric = metrics::kMetricFailedUpdateCount; 1268 LOG(INFO) << "Uploading " << target_attempt 1269 << " (count) for metric " << metric; 1270 system_state_->metrics_lib()->SendToUMA( 1271 metric, 1272 target_attempt, 1273 1, // min value 1274 50, // max value 1275 kNumDefaultUmaBuckets); 1276 } else { 1277 prefs_->Delete(kPrefsTargetVersionAttempt); 1278 prefs_->Delete(kPrefsTargetVersionUniqueId); 1279 } 1280 prefs_->Delete(kPrefsTargetVersionInstalledFrom); 1281 } 1282 } 1283 1284 void PayloadState::ExpectRebootInNewVersion(const string& target_version_uid) { 1285 // Expect to boot into the new partition in the next reboot setting the 1286 // TargetVersion* flags in the Prefs. 1287 string stored_target_version_uid; 1288 string target_version_id; 1289 string target_partition; 1290 int64_t target_attempt; 1291 1292 if (prefs_->Exists(kPrefsTargetVersionUniqueId) && 1293 prefs_->GetString(kPrefsTargetVersionUniqueId, 1294 &stored_target_version_uid) && 1295 stored_target_version_uid == target_version_uid) { 1296 if (!prefs_->GetInt64(kPrefsTargetVersionAttempt, &target_attempt)) 1297 target_attempt = 0; 1298 } else { 1299 prefs_->SetString(kPrefsTargetVersionUniqueId, target_version_uid); 1300 target_attempt = 0; 1301 } 1302 prefs_->SetInt64(kPrefsTargetVersionAttempt, target_attempt + 1); 1303 1304 prefs_->SetInt64(kPrefsTargetVersionInstalledFrom, 1305 system_state_->boot_control()->GetCurrentSlot()); 1306 } 1307 1308 void PayloadState::ResetUpdateStatus() { 1309 // Remove the TargetVersionInstalledFrom pref so that if the machine is 1310 // rebooted the next boot is not flagged as failed to rebooted into the 1311 // new applied payload. 1312 prefs_->Delete(kPrefsTargetVersionInstalledFrom); 1313 1314 // Also decrement the attempt number if it exists. 1315 int64_t target_attempt; 1316 if (prefs_->GetInt64(kPrefsTargetVersionAttempt, &target_attempt)) 1317 prefs_->SetInt64(kPrefsTargetVersionAttempt, target_attempt - 1); 1318 } 1319 1320 int PayloadState::GetP2PNumAttempts() { 1321 return p2p_num_attempts_; 1322 } 1323 1324 void PayloadState::SetP2PNumAttempts(int value) { 1325 p2p_num_attempts_ = value; 1326 LOG(INFO) << "p2p Num Attempts = " << p2p_num_attempts_; 1327 CHECK(prefs_); 1328 prefs_->SetInt64(kPrefsP2PNumAttempts, value); 1329 } 1330 1331 void PayloadState::LoadP2PNumAttempts() { 1332 SetP2PNumAttempts(GetPersistedValue(kPrefsP2PNumAttempts)); 1333 } 1334 1335 Time PayloadState::GetP2PFirstAttemptTimestamp() { 1336 return p2p_first_attempt_timestamp_; 1337 } 1338 1339 void PayloadState::SetP2PFirstAttemptTimestamp(const Time& time) { 1340 p2p_first_attempt_timestamp_ = time; 1341 LOG(INFO) << "p2p First Attempt Timestamp = " 1342 << utils::ToString(p2p_first_attempt_timestamp_); 1343 CHECK(prefs_); 1344 int64_t stored_value = time.ToInternalValue(); 1345 prefs_->SetInt64(kPrefsP2PFirstAttemptTimestamp, stored_value); 1346 } 1347 1348 void PayloadState::LoadP2PFirstAttemptTimestamp() { 1349 int64_t stored_value = GetPersistedValue(kPrefsP2PFirstAttemptTimestamp); 1350 Time stored_time = Time::FromInternalValue(stored_value); 1351 SetP2PFirstAttemptTimestamp(stored_time); 1352 } 1353 1354 void PayloadState::P2PNewAttempt() { 1355 CHECK(prefs_); 1356 // Set timestamp, if it hasn't been set already 1357 if (p2p_first_attempt_timestamp_.is_null()) { 1358 SetP2PFirstAttemptTimestamp(system_state_->clock()->GetWallclockTime()); 1359 } 1360 // Increase number of attempts 1361 SetP2PNumAttempts(GetP2PNumAttempts() + 1); 1362 } 1363 1364 bool PayloadState::P2PAttemptAllowed() { 1365 if (p2p_num_attempts_ > kMaxP2PAttempts) { 1366 LOG(INFO) << "Number of p2p attempts is " << p2p_num_attempts_ 1367 << " which is greater than " 1368 << kMaxP2PAttempts 1369 << " - disallowing p2p."; 1370 return false; 1371 } 1372 1373 if (!p2p_first_attempt_timestamp_.is_null()) { 1374 Time now = system_state_->clock()->GetWallclockTime(); 1375 TimeDelta time_spent_attempting_p2p = now - p2p_first_attempt_timestamp_; 1376 if (time_spent_attempting_p2p.InSeconds() < 0) { 1377 LOG(ERROR) << "Time spent attempting p2p is negative" 1378 << " - disallowing p2p."; 1379 return false; 1380 } 1381 if (time_spent_attempting_p2p.InSeconds() > kMaxP2PAttemptTimeSeconds) { 1382 LOG(INFO) << "Time spent attempting p2p is " 1383 << utils::FormatTimeDelta(time_spent_attempting_p2p) 1384 << " which is greater than " 1385 << utils::FormatTimeDelta(TimeDelta::FromSeconds( 1386 kMaxP2PAttemptTimeSeconds)) 1387 << " - disallowing p2p."; 1388 return false; 1389 } 1390 } 1391 1392 return true; 1393 } 1394 1395 } // namespace chromeos_update_engine 1396