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