update_attempter.cc revision b92f0df60b3b1d8ad0ac95fea74cc4fbbf93d204 
1// Copyright (c) 2012 The Chromium OS Authors. All rights reserved.
2// Use of this source code is governed by a BSD-style license that can be
3// found in the LICENSE file.
4
5#include "update_engine/update_attempter.h"
6
7// From 'man clock_gettime': feature test macro: _POSIX_C_SOURCE >= 199309L
8#ifndef _POSIX_C_SOURCE
9#define _POSIX_C_SOURCE 199309L
10#endif  // _POSIX_C_SOURCE
11#include <time.h>
12
13#include <string>
14#include <tr1/memory>
15#include <vector>
16
17#include <base/file_util.h>
18#include <base/rand_util.h>
19#include <glib.h>
20#include <metrics/metrics_library.h>
21#include <policy/libpolicy.h>
22#include <policy/device_policy.h>
23
24#include "update_engine/certificate_checker.h"
25#include "update_engine/dbus_service.h"
26#include "update_engine/download_action.h"
27#include "update_engine/filesystem_copier_action.h"
28#include "update_engine/gpio_handler.h"
29#include "update_engine/libcurl_http_fetcher.h"
30#include "update_engine/multi_range_http_fetcher.h"
31#include "update_engine/omaha_request_action.h"
32#include "update_engine/omaha_request_params.h"
33#include "update_engine/omaha_response_handler_action.h"
34#include "update_engine/payload_state_interface.h"
35#include "update_engine/postinstall_runner_action.h"
36#include "update_engine/prefs_interface.h"
37#include "update_engine/subprocess.h"
38#include "update_engine/system_state.h"
39#include "update_engine/update_check_scheduler.h"
40
41using base::TimeDelta;
42using base::TimeTicks;
43using google::protobuf::NewPermanentCallback;
44using std::make_pair;
45using std::tr1::shared_ptr;
46using std::set;
47using std::string;
48using std::vector;
49
50namespace chromeos_update_engine {
51
52const int UpdateAttempter::kMaxDeltaUpdateFailures = 3;
53
54// Private test server URL w/ custom port number.
55// TODO(garnold) This is a temporary hack to allow us to test the closed loop
56// automated update testing. To be replaced with an hard-coded local IP address.
57const char* const UpdateAttempter::kTestUpdateUrl(
58    "http://garnold.mtv.corp.google.com:8080/update");
59
60const char* kUpdateCompletedMarker =
61    "/var/run/update_engine_autoupdate_completed";
62
63namespace {
64const int kMaxConsecutiveObeyProxyRequests = 20;
65}  // namespace {}
66
67const char* UpdateStatusToString(UpdateStatus status) {
68  switch (status) {
69    case UPDATE_STATUS_IDLE:
70      return "UPDATE_STATUS_IDLE";
71    case UPDATE_STATUS_CHECKING_FOR_UPDATE:
72      return "UPDATE_STATUS_CHECKING_FOR_UPDATE";
73    case UPDATE_STATUS_UPDATE_AVAILABLE:
74      return "UPDATE_STATUS_UPDATE_AVAILABLE";
75    case UPDATE_STATUS_DOWNLOADING:
76      return "UPDATE_STATUS_DOWNLOADING";
77    case UPDATE_STATUS_VERIFYING:
78      return "UPDATE_STATUS_VERIFYING";
79    case UPDATE_STATUS_FINALIZING:
80      return "UPDATE_STATUS_FINALIZING";
81    case UPDATE_STATUS_UPDATED_NEED_REBOOT:
82      return "UPDATE_STATUS_UPDATED_NEED_REBOOT";
83    case UPDATE_STATUS_REPORTING_ERROR_EVENT:
84      return "UPDATE_STATUS_REPORTING_ERROR_EVENT";
85    default:
86      return "unknown status";
87  }
88}
89
90// Turns a generic kActionCodeError to a generic error code specific
91// to |action| (e.g., kActionCodeFilesystemCopierError). If |code| is
92// not kActionCodeError, or the action is not matched, returns |code|
93// unchanged.
94ActionExitCode GetErrorCodeForAction(AbstractAction* action,
95                                     ActionExitCode code) {
96  if (code != kActionCodeError)
97    return code;
98
99  const string type = action->Type();
100  if (type == OmahaRequestAction::StaticType())
101    return kActionCodeOmahaRequestError;
102  if (type == OmahaResponseHandlerAction::StaticType())
103    return kActionCodeOmahaResponseHandlerError;
104  if (type == FilesystemCopierAction::StaticType())
105    return kActionCodeFilesystemCopierError;
106  if (type == PostinstallRunnerAction::StaticType())
107    return kActionCodePostinstallRunnerError;
108
109  return code;
110}
111
112UpdateAttempter::UpdateAttempter(SystemState* system_state,
113                                 DbusGlibInterface* dbus_iface)
114    : processor_(new ActionProcessor()),
115      system_state_(system_state),
116      dbus_service_(NULL),
117      update_check_scheduler_(NULL),
118      fake_update_success_(false),
119      http_response_code_(0),
120      shares_(utils::kCpuSharesNormal),
121      manage_shares_source_(NULL),
122      download_active_(false),
123      status_(UPDATE_STATUS_IDLE),
124      download_progress_(0.0),
125      last_checked_time_(0),
126      new_version_("0.0.0.0"),
127      new_payload_size_(0),
128      proxy_manual_checks_(0),
129      obeying_proxies_(true),
130      chrome_proxy_resolver_(dbus_iface),
131      updated_boot_flags_(false),
132      update_boot_flags_running_(false),
133      start_action_processor_(false),
134      policy_provider_(NULL),
135      is_using_test_url_(false),
136      is_test_mode_(false),
137      is_test_update_attempted_(false) {
138  prefs_ = system_state->prefs();
139  if (utils::FileExists(kUpdateCompletedMarker))
140    status_ = UPDATE_STATUS_UPDATED_NEED_REBOOT;
141}
142
143UpdateAttempter::~UpdateAttempter() {
144  CleanupCpuSharesManagement();
145}
146
147void UpdateAttempter::Update(const string& app_version,
148                             const string& omaha_url,
149                             bool obey_proxies,
150                             bool interactive,
151                             bool is_test_mode) {
152  chrome_proxy_resolver_.Init();
153  fake_update_success_ = false;
154  if (status_ == UPDATE_STATUS_UPDATED_NEED_REBOOT) {
155    // Although we have applied an update, we still want to ping Omaha
156    // to ensure the number of active statistics is accurate.
157    LOG(INFO) << "Not updating b/c we already updated and we're waiting for "
158              << "reboot, we'll ping Omaha instead";
159    PingOmaha();
160    return;
161  }
162  if (status_ != UPDATE_STATUS_IDLE) {
163    // Update in progress. Do nothing
164    return;
165  }
166
167  if (!CalculateUpdateParams(app_version,
168                             omaha_url,
169                             obey_proxies,
170                             interactive,
171                             is_test_mode)) {
172    return;
173  }
174
175  BuildUpdateActions(interactive);
176
177  SetStatusAndNotify(UPDATE_STATUS_CHECKING_FOR_UPDATE,
178                     kUpdateNoticeUnspecified);
179
180  // Just in case we didn't update boot flags yet, make sure they're updated
181  // before any update processing starts.
182  start_action_processor_ = true;
183  UpdateBootFlags();
184}
185
186bool UpdateAttempter::CalculateUpdateParams(const string& app_version,
187                                            const string& omaha_url,
188                                            bool obey_proxies,
189                                            bool interactive,
190                                            bool is_test_mode) {
191  http_response_code_ = 0;
192
193  // Set the test mode flag for the current update attempt.
194  is_test_mode_ = is_test_mode;
195
196  // Lazy initialize the policy provider, or reload the latest policy data.
197  if (!policy_provider_.get()) {
198    policy_provider_.reset(new policy::PolicyProvider());
199  } else {
200    policy_provider_->Reload();
201  }
202
203  // If the release_track is specified by policy, that takes precedence.
204  string release_track;
205
206  if (policy_provider_->device_policy_is_loaded()) {
207    const policy::DevicePolicy& device_policy =
208                                policy_provider_->GetDevicePolicy();
209    device_policy.GetReleaseChannel(&release_track);
210    device_policy.GetUpdateDisabled(&omaha_request_params_.update_disabled);
211    device_policy.GetTargetVersionPrefix(
212      &omaha_request_params_.target_version_prefix);
213
214    system_state_->set_device_policy(&device_policy);
215
216    set<string> allowed_types;
217    string allowed_types_str;
218    if (device_policy.GetAllowedConnectionTypesForUpdate(&allowed_types)) {
219      set<string>::const_iterator iter;
220      for (iter = allowed_types.begin(); iter != allowed_types.end(); ++iter)
221        allowed_types_str += *iter + " ";
222    }
223
224    LOG(INFO) << "Networks over which updates are allowed per policy : "
225              << (allowed_types_str.empty() ? "all" : allowed_types_str);
226  } else {
227    LOG(INFO) << "No device policies present.";
228    system_state_->set_device_policy(NULL);
229  }
230
231  CalculateScatteringParams(interactive);
232
233  // Determine whether an alternative test address should be used.
234  string omaha_url_to_use = omaha_url;
235  if ((is_using_test_url_ = (omaha_url_to_use.empty() && is_test_mode_))) {
236    omaha_url_to_use = kTestUpdateUrl;
237    LOG(INFO) << "using alternative server address: " << omaha_url_to_use;
238  }
239
240  if (!omaha_request_params_.Init(app_version,
241                                  omaha_url_to_use,
242                                  release_track,
243                                  interactive)) {
244    LOG(ERROR) << "Unable to initialize Omaha request device params.";
245    return false;
246  }
247
248  LOG(INFO) << "update_disabled = "
249            << (omaha_request_params_.update_disabled ? "true" : "false")
250            << ", target_version_prefix = "
251            << omaha_request_params_.target_version_prefix
252            << ", scatter_factor_in_seconds = "
253            << utils::FormatSecs(scatter_factor_.InSeconds());
254
255  LOG(INFO) << "Wall Clock Based Wait Enabled = "
256            << omaha_request_params_.wall_clock_based_wait_enabled
257            << ", Update Check Count Wait Enabled = "
258            << omaha_request_params_.update_check_count_wait_enabled
259            << ", Waiting Period = " << utils::FormatSecs(
260               omaha_request_params_.waiting_period.InSeconds());
261
262  obeying_proxies_ = true;
263  if (obey_proxies || proxy_manual_checks_ == 0) {
264    LOG(INFO) << "forced to obey proxies";
265    // If forced to obey proxies, every 20th request will not use proxies
266    proxy_manual_checks_++;
267    LOG(INFO) << "proxy manual checks: " << proxy_manual_checks_;
268    if (proxy_manual_checks_ >= kMaxConsecutiveObeyProxyRequests) {
269      proxy_manual_checks_ = 0;
270      obeying_proxies_ = false;
271    }
272  } else if (base::RandInt(0, 4) == 0) {
273    obeying_proxies_ = false;
274  }
275  LOG_IF(INFO, !obeying_proxies_) << "To help ensure updates work, this update "
276      "check we are ignoring the proxy settings and using "
277      "direct connections.";
278
279  DisableDeltaUpdateIfNeeded();
280  return true;
281}
282
283void UpdateAttempter::CalculateScatteringParams(bool interactive) {
284  // Take a copy of the old scatter value before we update it, as
285  // we need to update the waiting period if this value changes.
286  TimeDelta old_scatter_factor = scatter_factor_;
287  const policy::DevicePolicy* device_policy = system_state_->device_policy();
288  if (device_policy) {
289    int64 new_scatter_factor_in_secs = 0;
290    device_policy->GetScatterFactorInSeconds(&new_scatter_factor_in_secs);
291    if (new_scatter_factor_in_secs < 0) // sanitize input, just in case.
292      new_scatter_factor_in_secs  = 0;
293    scatter_factor_ = TimeDelta::FromSeconds(new_scatter_factor_in_secs);
294  }
295
296  bool is_scatter_enabled = false;
297  if (scatter_factor_.InSeconds() == 0) {
298    LOG(INFO) << "Scattering disabled since scatter factor is set to 0";
299  } else if (interactive) {
300    LOG(INFO) << "Scattering disabled as this is an interactive update check";
301  } else if (!system_state_->IsOOBEComplete()) {
302    LOG(INFO) << "Scattering disabled since OOBE is not complete yet";
303  } else {
304    is_scatter_enabled = true;
305    LOG(INFO) << "Scattering is enabled";
306  }
307
308  if (is_scatter_enabled) {
309    // This means the scattering policy is turned on.
310    // Now check if we need to update the waiting period. The two cases
311    // in which we'd need to update the waiting period are:
312    // 1. First time in process or a scheduled check after a user-initiated one.
313    //    (omaha_request_params_.waiting_period will be zero in this case).
314    // 2. Admin has changed the scattering policy value.
315    //    (new scattering value will be different from old one in this case).
316    int64 wait_period_in_secs = 0;
317    if (omaha_request_params_.waiting_period.InSeconds() == 0) {
318      // First case. Check if we have a suitable value to set for
319      // the waiting period.
320      if (prefs_->GetInt64(kPrefsWallClockWaitPeriod, &wait_period_in_secs) &&
321          wait_period_in_secs > 0 &&
322          wait_period_in_secs <= scatter_factor_.InSeconds()) {
323        // This means:
324        // 1. There's a persisted value for the waiting period available.
325        // 2. And that persisted value is still valid.
326        // So, in this case, we should reuse the persisted value instead of
327        // generating a new random value to improve the chances of a good
328        // distribution for scattering.
329        omaha_request_params_.waiting_period =
330          TimeDelta::FromSeconds(wait_period_in_secs);
331        LOG(INFO) << "Using persisted wall-clock waiting period: " <<
332            utils::FormatSecs(omaha_request_params_.waiting_period.InSeconds());
333      }
334      else {
335        // This means there's no persisted value for the waiting period
336        // available or its value is invalid given the new scatter_factor value.
337        // So, we should go ahead and regenerate a new value for the
338        // waiting period.
339        LOG(INFO) << "Persisted value not present or not valid ("
340                  << utils::FormatSecs(wait_period_in_secs)
341                  << ") for wall-clock waiting period.";
342        GenerateNewWaitingPeriod();
343      }
344    } else if (scatter_factor_ != old_scatter_factor) {
345      // This means there's already a waiting period value, but we detected
346      // a change in the scattering policy value. So, we should regenerate the
347      // waiting period to make sure it's within the bounds of the new scatter
348      // factor value.
349      GenerateNewWaitingPeriod();
350    } else {
351      // Neither the first time scattering is enabled nor the scattering value
352      // changed. Nothing to do.
353      LOG(INFO) << "Keeping current wall-clock waiting period: " <<
354          utils::FormatSecs(omaha_request_params_.waiting_period.InSeconds());
355    }
356
357    // The invariant at this point is that omaha_request_params_.waiting_period
358    // is non-zero no matter which path we took above.
359    LOG_IF(ERROR, omaha_request_params_.waiting_period.InSeconds() == 0)
360        << "Waiting Period should NOT be zero at this point!!!";
361
362    // Since scattering is enabled, wall clock based wait will always be
363    // enabled.
364    omaha_request_params_.wall_clock_based_wait_enabled = true;
365
366    // If we don't have any issues in accessing the file system to update
367    // the update check count value, we'll turn that on as well.
368    bool decrement_succeeded = DecrementUpdateCheckCount();
369    omaha_request_params_.update_check_count_wait_enabled = decrement_succeeded;
370  } else {
371    // This means the scattering feature is turned off or disabled for
372    // this particular update check. Make sure to disable
373    // all the knobs and artifacts so that we don't invoke any scattering
374    // related code.
375    omaha_request_params_.wall_clock_based_wait_enabled = false;
376    omaha_request_params_.update_check_count_wait_enabled = false;
377    omaha_request_params_.waiting_period = TimeDelta::FromSeconds(0);
378    prefs_->Delete(kPrefsWallClockWaitPeriod);
379    prefs_->Delete(kPrefsUpdateCheckCount);
380    // Don't delete the UpdateFirstSeenAt file as we don't want manual checks
381    // that result in no-updates (e.g. due to server side throttling) to
382    // cause update starvation by having the client generate a new
383    // UpdateFirstSeenAt for each scheduled check that follows a manual check.
384  }
385}
386
387void UpdateAttempter::GenerateNewWaitingPeriod() {
388  omaha_request_params_.waiting_period = TimeDelta::FromSeconds(
389      base::RandInt(1, scatter_factor_.InSeconds()));
390
391  LOG(INFO) << "Generated new wall-clock waiting period: " << utils::FormatSecs(
392                omaha_request_params_.waiting_period.InSeconds());
393
394  // Do a best-effort to persist this in all cases. Even if the persistence
395  // fails, we'll still be able to scatter based on our in-memory value.
396  // The persistence only helps in ensuring a good overall distribution
397  // across multiple devices if they tend to reboot too often.
398  prefs_->SetInt64(kPrefsWallClockWaitPeriod,
399                   omaha_request_params_.waiting_period.InSeconds());
400}
401
402void UpdateAttempter::BuildUpdateActions(bool interactive) {
403  CHECK(!processor_->IsRunning());
404  processor_->set_delegate(this);
405
406  // Actions:
407  LibcurlHttpFetcher* update_check_fetcher =
408      new LibcurlHttpFetcher(GetProxyResolver(), system_state_, is_test_mode_);
409  // Try harder to connect to the network, esp when not interactive.
410  // See comment in libcurl_http_fetcher.cc.
411  update_check_fetcher->set_no_network_max_retries(interactive ? 1 : 3);
412  update_check_fetcher->set_check_certificate(CertificateChecker::kUpdate);
413  shared_ptr<OmahaRequestAction> update_check_action(
414      new OmahaRequestAction(system_state_,
415                             &omaha_request_params_,
416                             NULL,
417                             update_check_fetcher,  // passes ownership
418                             false));
419  shared_ptr<OmahaResponseHandlerAction> response_handler_action(
420      new OmahaResponseHandlerAction(system_state_));
421  shared_ptr<FilesystemCopierAction> filesystem_copier_action(
422      new FilesystemCopierAction(false, false));
423  shared_ptr<FilesystemCopierAction> kernel_filesystem_copier_action(
424      new FilesystemCopierAction(true, false));
425  shared_ptr<OmahaRequestAction> download_started_action(
426      new OmahaRequestAction(system_state_,
427                             &omaha_request_params_,
428                             new OmahaEvent(
429                                 OmahaEvent::kTypeUpdateDownloadStarted),
430                             new LibcurlHttpFetcher(GetProxyResolver(),
431                                                    system_state_,
432                                                    is_test_mode_),
433                             false));
434  LibcurlHttpFetcher* download_fetcher =
435      new LibcurlHttpFetcher(GetProxyResolver(), system_state_, is_test_mode_);
436  download_fetcher->set_check_certificate(CertificateChecker::kDownload);
437  shared_ptr<DownloadAction> download_action(
438      new DownloadAction(prefs_,
439                         system_state_,
440                         new MultiRangeHttpFetcher(
441                             download_fetcher)));  // passes ownership
442  shared_ptr<OmahaRequestAction> download_finished_action(
443      new OmahaRequestAction(system_state_,
444                             &omaha_request_params_,
445                             new OmahaEvent(
446                                 OmahaEvent::kTypeUpdateDownloadFinished),
447                             new LibcurlHttpFetcher(GetProxyResolver(),
448                                                    system_state_,
449                                                    is_test_mode_),
450                             false));
451  shared_ptr<FilesystemCopierAction> filesystem_verifier_action(
452      new FilesystemCopierAction(false, true));
453  shared_ptr<FilesystemCopierAction> kernel_filesystem_verifier_action(
454      new FilesystemCopierAction(true, true));
455  shared_ptr<PostinstallRunnerAction> postinstall_runner_action(
456      new PostinstallRunnerAction);
457  shared_ptr<OmahaRequestAction> update_complete_action(
458      new OmahaRequestAction(system_state_,
459                             &omaha_request_params_,
460                             new OmahaEvent(OmahaEvent::kTypeUpdateComplete),
461                             new LibcurlHttpFetcher(GetProxyResolver(),
462                                                    system_state_,
463                                                    is_test_mode_),
464                             false));
465
466  download_action->set_delegate(this);
467  response_handler_action_ = response_handler_action;
468  download_action_ = download_action;
469
470  actions_.push_back(shared_ptr<AbstractAction>(update_check_action));
471  actions_.push_back(shared_ptr<AbstractAction>(response_handler_action));
472  actions_.push_back(shared_ptr<AbstractAction>(filesystem_copier_action));
473  actions_.push_back(shared_ptr<AbstractAction>(
474      kernel_filesystem_copier_action));
475  actions_.push_back(shared_ptr<AbstractAction>(download_started_action));
476  actions_.push_back(shared_ptr<AbstractAction>(download_action));
477  actions_.push_back(shared_ptr<AbstractAction>(download_finished_action));
478  actions_.push_back(shared_ptr<AbstractAction>(filesystem_verifier_action));
479  actions_.push_back(shared_ptr<AbstractAction>(
480      kernel_filesystem_verifier_action));
481  actions_.push_back(shared_ptr<AbstractAction>(postinstall_runner_action));
482  actions_.push_back(shared_ptr<AbstractAction>(update_complete_action));
483
484  // Enqueue the actions
485  for (vector<shared_ptr<AbstractAction> >::iterator it = actions_.begin();
486       it != actions_.end(); ++it) {
487    processor_->EnqueueAction(it->get());
488  }
489
490  // Bond them together. We have to use the leaf-types when calling
491  // BondActions().
492  BondActions(update_check_action.get(),
493              response_handler_action.get());
494  BondActions(response_handler_action.get(),
495              filesystem_copier_action.get());
496  BondActions(filesystem_copier_action.get(),
497              kernel_filesystem_copier_action.get());
498  BondActions(kernel_filesystem_copier_action.get(),
499              download_action.get());
500  BondActions(download_action.get(),
501              filesystem_verifier_action.get());
502  BondActions(filesystem_verifier_action.get(),
503              kernel_filesystem_verifier_action.get());
504  BondActions(kernel_filesystem_verifier_action.get(),
505              postinstall_runner_action.get());
506}
507
508void UpdateAttempter::CheckForUpdate(const string& app_version,
509                                     const string& omaha_url,
510                                     bool interactive) {
511  LOG(INFO) << "New update check requested";
512
513  if (status_ != UPDATE_STATUS_IDLE) {
514    LOG(INFO) << "Skipping update check because current status is "
515              << UpdateStatusToString(status_);
516    return;
517  }
518
519  // Read GPIO signals and determine whether this is an automated test scenario.
520  // For safety, we only allow a test update to be performed once; subsequent
521  // update requests will be carried out normally.
522  bool is_test_mode = (!is_test_update_attempted_ &&
523                       system_state_->gpio_handler()->IsTestModeSignaled());
524  if (is_test_mode) {
525    LOG(WARNING) << "this is a test mode update attempt!";
526    is_test_update_attempted_ = true;
527  }
528
529  // Pass through the interactive flag, in case we want to simulate a scheduled
530  // test.
531  Update(app_version, omaha_url, true, interactive, is_test_mode);
532}
533
534bool UpdateAttempter::RebootIfNeeded() {
535  if (status_ != UPDATE_STATUS_UPDATED_NEED_REBOOT) {
536    LOG(INFO) << "Reboot requested, but status is "
537              << UpdateStatusToString(status_) << ", so not rebooting.";
538    return false;
539  }
540  TEST_AND_RETURN_FALSE(utils::Reboot());
541  return true;
542}
543
544// Delegate methods:
545void UpdateAttempter::ProcessingDone(const ActionProcessor* processor,
546                                     ActionExitCode code) {
547  CHECK(response_handler_action_);
548  LOG(INFO) << "Processing Done.";
549  actions_.clear();
550
551  // Reset cpu shares back to normal.
552  CleanupCpuSharesManagement();
553
554  if (status_ == UPDATE_STATUS_REPORTING_ERROR_EVENT) {
555    LOG(INFO) << "Error event sent.";
556
557    // Inform scheduler of new status; also specifically inform about a failed
558    // update attempt with a test address.
559    SetStatusAndNotify(UPDATE_STATUS_IDLE,
560                       (is_using_test_url_ ? kUpdateNoticeTestAddrFailed :
561                        kUpdateNoticeUnspecified));
562
563    if (!fake_update_success_) {
564      return;
565    }
566    LOG(INFO) << "Booted from FW B and tried to install new firmware, "
567        "so requesting reboot from user.";
568  }
569
570  if (code == kActionCodeSuccess) {
571    utils::WriteFile(kUpdateCompletedMarker, "", 0);
572    prefs_->SetInt64(kPrefsDeltaUpdateFailures, 0);
573    prefs_->SetString(kPrefsPreviousVersion, omaha_request_params_.app_version);
574    DeltaPerformer::ResetUpdateProgress(prefs_, false);
575
576    // Since we're done with scattering fully at this point, this is the
577    // safest point delete the state files, as we're sure that the status is
578    // set to reboot (which means no more updates will be applied until reboot)
579    // This deletion is required for correctness as we want the next update
580    // check to re-create a new random number for the update check count.
581    // Similarly, we also delete the wall-clock-wait period that was persisted
582    // so that we start with a new random value for the next update check
583    // after reboot so that the same device is not favored or punished in any
584    // way.
585    prefs_->Delete(kPrefsUpdateCheckCount);
586    prefs_->Delete(kPrefsWallClockWaitPeriod);
587    prefs_->Delete(kPrefsUpdateFirstSeenAt);
588    LOG(INFO) << "Update successfully applied, waiting to reboot.";
589
590    SetStatusAndNotify(UPDATE_STATUS_UPDATED_NEED_REBOOT,
591                       kUpdateNoticeUnspecified);
592
593    // Report the time it took to update the system.
594    int64_t update_time = time(NULL) - last_checked_time_;
595    if (!fake_update_success_)
596      system_state_->metrics_lib()->SendToUMA(
597          "Installer.UpdateTime",
598           static_cast<int>(update_time),  // sample
599           1,  // min = 1 second
600           20 * 60,  // max = 20 minutes
601           50);  // buckets
602
603    // Also report the success code so that the percentiles can be
604    // interpreted properly for the remaining error codes in UMA.
605    utils::SendErrorCodeToUma(system_state_, code);
606    return;
607  }
608
609  if (ScheduleErrorEventAction()) {
610    return;
611  }
612  LOG(INFO) << "No update.";
613  SetStatusAndNotify(UPDATE_STATUS_IDLE, kUpdateNoticeUnspecified);
614}
615
616void UpdateAttempter::ProcessingStopped(const ActionProcessor* processor) {
617  // Reset cpu shares back to normal.
618  CleanupCpuSharesManagement();
619  download_progress_ = 0.0;
620  SetStatusAndNotify(UPDATE_STATUS_IDLE, kUpdateNoticeUnspecified);
621  actions_.clear();
622  error_event_.reset(NULL);
623}
624
625// Called whenever an action has finished processing, either successfully
626// or otherwise.
627void UpdateAttempter::ActionCompleted(ActionProcessor* processor,
628                                      AbstractAction* action,
629                                      ActionExitCode code) {
630  // Reset download progress regardless of whether or not the download
631  // action succeeded. Also, get the response code from HTTP request
632  // actions (update download as well as the initial update check
633  // actions).
634  const string type = action->Type();
635  if (type == DownloadAction::StaticType()) {
636    download_progress_ = 0.0;
637    DownloadAction* download_action = dynamic_cast<DownloadAction*>(action);
638    http_response_code_ = download_action->GetHTTPResponseCode();
639  } else if (type == OmahaRequestAction::StaticType()) {
640    OmahaRequestAction* omaha_request_action =
641        dynamic_cast<OmahaRequestAction*>(action);
642    // If the request is not an event, then it's the update-check.
643    if (!omaha_request_action->IsEvent()) {
644      http_response_code_ = omaha_request_action->GetHTTPResponseCode();
645      // Forward the server-dictated poll interval to the update check
646      // scheduler, if any.
647      if (update_check_scheduler_) {
648        update_check_scheduler_->set_poll_interval(
649            omaha_request_action->GetOutputObject().poll_interval);
650      }
651    }
652  }
653  if (code != kActionCodeSuccess) {
654    // If the current state is at or past the download phase, count the failure
655    // in case a switch to full update becomes necessary. Ignore network
656    // transfer timeouts and failures.
657    if (status_ >= UPDATE_STATUS_DOWNLOADING &&
658        code != kActionCodeDownloadTransferError) {
659      MarkDeltaUpdateFailure();
660    }
661    // On failure, schedule an error event to be sent to Omaha.
662    CreatePendingErrorEvent(action, code);
663    return;
664  }
665  // Find out which action completed.
666  if (type == OmahaResponseHandlerAction::StaticType()) {
667    // Note that the status will be updated to DOWNLOADING when some bytes get
668    // actually downloaded from the server and the BytesReceived callback is
669    // invoked. This avoids notifying the user that a download has started in
670    // cases when the server and the client are unable to initiate the download.
671    CHECK(action == response_handler_action_.get());
672    const InstallPlan& plan = response_handler_action_->install_plan();
673    last_checked_time_ = time(NULL);
674    // TODO(adlr): put version in InstallPlan
675    new_version_ = "0.0.0.0";
676    new_payload_size_ = plan.payload_size;
677    SetupDownload();
678    SetupCpuSharesManagement();
679    SetStatusAndNotify(UPDATE_STATUS_UPDATE_AVAILABLE,
680                       kUpdateNoticeUnspecified);
681  } else if (type == DownloadAction::StaticType()) {
682    SetStatusAndNotify(UPDATE_STATUS_FINALIZING, kUpdateNoticeUnspecified);
683  }
684}
685
686// Stop updating. An attempt will be made to record status to the disk
687// so that updates can be resumed later.
688void UpdateAttempter::Terminate() {
689  // TODO(adlr): implement this method.
690  NOTIMPLEMENTED();
691}
692
693// Try to resume from a previously Terminate()d update.
694void UpdateAttempter::ResumeUpdating() {
695  // TODO(adlr): implement this method.
696  NOTIMPLEMENTED();
697}
698
699void UpdateAttempter::SetDownloadStatus(bool active) {
700  download_active_ = active;
701  LOG(INFO) << "Download status: " << (active ? "active" : "inactive");
702}
703
704void UpdateAttempter::BytesReceived(uint64_t bytes_received, uint64_t total) {
705  if (!download_active_) {
706    LOG(ERROR) << "BytesReceived called while not downloading.";
707    return;
708  }
709  double progress = static_cast<double>(bytes_received) /
710      static_cast<double>(total);
711  // Self throttle based on progress. Also send notifications if
712  // progress is too slow.
713  const double kDeltaPercent = 0.01;  // 1%
714  if (status_ != UPDATE_STATUS_DOWNLOADING ||
715      bytes_received == total ||
716      progress - download_progress_ >= kDeltaPercent ||
717      TimeTicks::Now() - last_notify_time_ >= TimeDelta::FromSeconds(10)) {
718    download_progress_ = progress;
719    SetStatusAndNotify(UPDATE_STATUS_DOWNLOADING, kUpdateNoticeUnspecified);
720  }
721}
722
723bool UpdateAttempter::ResetStatus() {
724  LOG(INFO) << "Attempting to reset state from "
725            << UpdateStatusToString(status_) << " to UPDATE_STATUS_IDLE";
726
727  switch (status_) {
728    case UPDATE_STATUS_IDLE:
729      // no-op.
730      return true;
731
732    case UPDATE_STATUS_UPDATED_NEED_REBOOT:  {
733      status_ = UPDATE_STATUS_IDLE;
734      LOG(INFO) << "Reset Successful";
735
736      // also remove the reboot marker so that if the machine is rebooted
737      // after resetting to idle state, it doesn't go back to
738      // UPDATE_STATUS_UPDATED_NEED_REBOOT state.
739      const FilePath kUpdateCompletedMarkerPath(kUpdateCompletedMarker);
740      return file_util::Delete(kUpdateCompletedMarkerPath, false);
741    }
742
743    default:
744      LOG(ERROR) << "Reset not allowed in this state.";
745      return false;
746  }
747}
748
749bool UpdateAttempter::GetStatus(int64_t* last_checked_time,
750                                double* progress,
751                                string* current_operation,
752                                string* new_version,
753                                int64_t* new_payload_size) {
754  *last_checked_time = last_checked_time_;
755  *progress = download_progress_;
756  *current_operation = UpdateStatusToString(status_);
757  *new_version = new_version_;
758  *new_payload_size = new_payload_size_;
759  return true;
760}
761
762void UpdateAttempter::UpdateBootFlags() {
763  if (update_boot_flags_running_) {
764    LOG(INFO) << "Update boot flags running, nothing to do.";
765    return;
766  }
767  if (updated_boot_flags_) {
768    LOG(INFO) << "Already updated boot flags. Skipping.";
769    if (start_action_processor_) {
770      ScheduleProcessingStart();
771    }
772    return;
773  }
774  // This is purely best effort. Failures should be logged by Subprocess. Run
775  // the script asynchronously to avoid blocking the event loop regardless of
776  // the script runtime.
777  update_boot_flags_running_ = true;
778  LOG(INFO) << "Updating boot flags...";
779  vector<string> cmd(1, "/usr/sbin/chromeos-setgoodkernel");
780  if (!Subprocess::Get().Exec(cmd, StaticCompleteUpdateBootFlags, this)) {
781    CompleteUpdateBootFlags(1);
782  }
783}
784
785void UpdateAttempter::CompleteUpdateBootFlags(int return_code) {
786  update_boot_flags_running_ = false;
787  updated_boot_flags_ = true;
788  if (start_action_processor_) {
789    ScheduleProcessingStart();
790  }
791}
792
793void UpdateAttempter::StaticCompleteUpdateBootFlags(
794    int return_code,
795    const string& output,
796    void* p) {
797  reinterpret_cast<UpdateAttempter*>(p)->CompleteUpdateBootFlags(return_code);
798}
799
800void UpdateAttempter::BroadcastStatus() {
801  if (!dbus_service_) {
802    return;
803  }
804  last_notify_time_ = TimeTicks::Now();
805  update_engine_service_emit_status_update(
806      dbus_service_,
807      last_checked_time_,
808      download_progress_,
809      UpdateStatusToString(status_),
810      new_version_.c_str(),
811      new_payload_size_);
812}
813
814uint32_t UpdateAttempter::GetErrorCodeFlags()  {
815  uint32_t flags = 0;
816
817  if (!utils::IsNormalBootMode())
818    flags |= kActionCodeDevModeFlag;
819
820  if (response_handler_action_.get() &&
821      response_handler_action_->install_plan().is_resume)
822    flags |= kActionCodeResumedFlag;
823
824  if (!utils::IsOfficialBuild())
825    flags |= kActionCodeTestImageFlag;
826
827  if (omaha_request_params_.update_url != kProductionOmahaUrl)
828    flags |= kActionCodeTestOmahaUrlFlag;
829
830  return flags;
831}
832
833void UpdateAttempter::SetStatusAndNotify(UpdateStatus status,
834                                         UpdateNotice notice) {
835  status_ = status;
836  if (update_check_scheduler_) {
837    update_check_scheduler_->SetUpdateStatus(status_, notice);
838  }
839  BroadcastStatus();
840}
841
842void UpdateAttempter::CreatePendingErrorEvent(AbstractAction* action,
843                                              ActionExitCode code) {
844  if (error_event_.get()) {
845    // This shouldn't really happen.
846    LOG(WARNING) << "There's already an existing pending error event.";
847    return;
848  }
849
850  // For now assume that a generic Omaha response action failure means that
851  // there's no update so don't send an event. Also, double check that the
852  // failure has not occurred while sending an error event -- in which case
853  // don't schedule another. This shouldn't really happen but just in case...
854  if ((action->Type() == OmahaResponseHandlerAction::StaticType() &&
855       code == kActionCodeError) ||
856      status_ == UPDATE_STATUS_REPORTING_ERROR_EVENT) {
857    return;
858  }
859
860  // Classify the code to generate the appropriate result so that
861  // the Borgmon charts show up the results correctly.
862  // Do this before calling GetErrorCodeForAction which could potentially
863  // augment the bit representation of code and thus cause no matches for
864  // the switch cases below.
865  OmahaEvent::Result event_result;
866  switch (code) {
867    case kActionCodeOmahaUpdateIgnoredPerPolicy:
868    case kActionCodeOmahaUpdateDeferredPerPolicy:
869    case kActionCodeOmahaUpdateDeferredForBackoff:
870      event_result = OmahaEvent::kResultUpdateDeferred;
871      break;
872    default:
873      event_result = OmahaEvent::kResultError;
874      break;
875  }
876
877  code = GetErrorCodeForAction(action, code);
878  fake_update_success_ = code == kActionCodePostinstallBootedFromFirmwareB;
879
880  // Compute the final error code with all the bit flags to be sent to Omaha.
881  code = static_cast<ActionExitCode>(code | GetErrorCodeFlags());
882  error_event_.reset(new OmahaEvent(OmahaEvent::kTypeUpdateComplete,
883                                    event_result,
884                                    code));
885}
886
887bool UpdateAttempter::ScheduleErrorEventAction() {
888  if (error_event_.get() == NULL)
889    return false;
890
891  LOG(ERROR) << "Update failed.";
892  system_state_->payload_state()->UpdateFailed(error_event_->error_code);
893
894  // Send it to Uma.
895  LOG(INFO) << "Reporting the error event";
896  utils::SendErrorCodeToUma(system_state_, error_event_->error_code);
897
898  // Send it to Omaha.
899  shared_ptr<OmahaRequestAction> error_event_action(
900      new OmahaRequestAction(system_state_,
901                             &omaha_request_params_,
902                             error_event_.release(),  // Pass ownership.
903                             new LibcurlHttpFetcher(GetProxyResolver(),
904                                                    system_state_,
905                                                    is_test_mode_),
906                             false));
907  actions_.push_back(shared_ptr<AbstractAction>(error_event_action));
908  processor_->EnqueueAction(error_event_action.get());
909  SetStatusAndNotify(UPDATE_STATUS_REPORTING_ERROR_EVENT,
910                     kUpdateNoticeUnspecified);
911  processor_->StartProcessing();
912  return true;
913}
914
915void UpdateAttempter::SetCpuShares(utils::CpuShares shares) {
916  if (shares_ == shares) {
917    return;
918  }
919  if (utils::SetCpuShares(shares)) {
920    shares_ = shares;
921    LOG(INFO) << "CPU shares = " << shares_;
922  }
923}
924
925void UpdateAttempter::SetupCpuSharesManagement() {
926  if (manage_shares_source_) {
927    LOG(ERROR) << "Cpu shares timeout source hasn't been destroyed.";
928    CleanupCpuSharesManagement();
929  }
930  const int kCpuSharesTimeout = 2 * 60 * 60;  // 2 hours
931  manage_shares_source_ = g_timeout_source_new_seconds(kCpuSharesTimeout);
932  g_source_set_callback(manage_shares_source_,
933                        StaticManageCpuSharesCallback,
934                        this,
935                        NULL);
936  g_source_attach(manage_shares_source_, NULL);
937  SetCpuShares(utils::kCpuSharesLow);
938}
939
940void UpdateAttempter::CleanupCpuSharesManagement() {
941  if (manage_shares_source_) {
942    g_source_destroy(manage_shares_source_);
943    manage_shares_source_ = NULL;
944  }
945  SetCpuShares(utils::kCpuSharesNormal);
946}
947
948gboolean UpdateAttempter::StaticManageCpuSharesCallback(gpointer data) {
949  return reinterpret_cast<UpdateAttempter*>(data)->ManageCpuSharesCallback();
950}
951
952gboolean UpdateAttempter::StaticStartProcessing(gpointer data) {
953  reinterpret_cast<UpdateAttempter*>(data)->processor_->StartProcessing();
954  return FALSE;  // Don't call this callback again.
955}
956
957void UpdateAttempter::ScheduleProcessingStart() {
958  LOG(INFO) << "Scheduling an action processor start.";
959  start_action_processor_ = false;
960  g_idle_add(&StaticStartProcessing, this);
961}
962
963bool UpdateAttempter::ManageCpuSharesCallback() {
964  SetCpuShares(utils::kCpuSharesNormal);
965  manage_shares_source_ = NULL;
966  return false;  // Destroy the timeout source.
967}
968
969void UpdateAttempter::DisableDeltaUpdateIfNeeded() {
970  int64_t delta_failures;
971  if (omaha_request_params_.delta_okay &&
972      prefs_->GetInt64(kPrefsDeltaUpdateFailures, &delta_failures) &&
973      delta_failures >= kMaxDeltaUpdateFailures) {
974    LOG(WARNING) << "Too many delta update failures, forcing full update.";
975    omaha_request_params_.delta_okay = false;
976  }
977}
978
979void UpdateAttempter::MarkDeltaUpdateFailure() {
980  // Don't try to resume a failed delta update.
981  DeltaPerformer::ResetUpdateProgress(prefs_, false);
982  int64_t delta_failures;
983  if (!prefs_->GetInt64(kPrefsDeltaUpdateFailures, &delta_failures) ||
984      delta_failures < 0) {
985    delta_failures = 0;
986  }
987  prefs_->SetInt64(kPrefsDeltaUpdateFailures, ++delta_failures);
988}
989
990void UpdateAttempter::SetupDownload() {
991  MultiRangeHttpFetcher* fetcher =
992      dynamic_cast<MultiRangeHttpFetcher*>(download_action_->http_fetcher());
993  fetcher->ClearRanges();
994  if (response_handler_action_->install_plan().is_resume) {
995    // Resuming an update so fetch the update manifest metadata first.
996    int64_t manifest_metadata_size = 0;
997    prefs_->GetInt64(kPrefsManifestMetadataSize, &manifest_metadata_size);
998    fetcher->AddRange(0, manifest_metadata_size);
999    // If there're remaining unprocessed data blobs, fetch them. Be careful not
1000    // to request data beyond the end of the payload to avoid 416 HTTP response
1001    // error codes.
1002    int64_t next_data_offset = 0;
1003    prefs_->GetInt64(kPrefsUpdateStateNextDataOffset, &next_data_offset);
1004    uint64_t resume_offset = manifest_metadata_size + next_data_offset;
1005    if (resume_offset < response_handler_action_->install_plan().payload_size) {
1006      fetcher->AddRange(resume_offset);
1007    }
1008  } else {
1009    fetcher->AddRange(0);
1010  }
1011}
1012
1013void UpdateAttempter::PingOmaha() {
1014  if (!processor_->IsRunning()) {
1015    shared_ptr<OmahaRequestAction> ping_action(
1016        new OmahaRequestAction(system_state_,
1017                               &omaha_request_params_,
1018                               NULL,
1019                               new LibcurlHttpFetcher(GetProxyResolver(),
1020                                                      system_state_,
1021                                                      is_test_mode_),
1022                               true));
1023    actions_.push_back(shared_ptr<OmahaRequestAction>(ping_action));
1024    processor_->set_delegate(NULL);
1025    processor_->EnqueueAction(ping_action.get());
1026    // Call StartProcessing() synchronously here to avoid any race conditions
1027    // caused by multiple outstanding ping Omaha requests.  If we call
1028    // StartProcessing() asynchronously, the device can be suspended before we
1029    // get a chance to callback to StartProcessing().  When the device resumes
1030    // (assuming the device sleeps longer than the next update check period),
1031    // StartProcessing() is called back and at the same time, the next update
1032    // check is fired which eventually invokes StartProcessing().  A crash
1033    // can occur because StartProcessing() checks to make sure that the
1034    // processor is idle which it isn't due to the two concurrent ping Omaha
1035    // requests.
1036    processor_->StartProcessing();
1037  } else {
1038    LOG(WARNING) << "Action processor running, Omaha ping suppressed.";
1039  }
1040
1041  // Update the status which will schedule the next update check
1042  SetStatusAndNotify(UPDATE_STATUS_UPDATED_NEED_REBOOT,
1043                     kUpdateNoticeUnspecified);
1044}
1045
1046
1047bool UpdateAttempter::DecrementUpdateCheckCount() {
1048  int64 update_check_count_value;
1049
1050  if (!prefs_->Exists(kPrefsUpdateCheckCount)) {
1051    // This file does not exist. This means we haven't started our update
1052    // check count down yet, so nothing more to do. This file will be created
1053    // later when we first satisfy the wall-clock-based-wait period.
1054    LOG(INFO) << "No existing update check count. That's normal.";
1055    return true;
1056  }
1057
1058  if (prefs_->GetInt64(kPrefsUpdateCheckCount, &update_check_count_value)) {
1059    // Only if we're able to read a proper integer value, then go ahead
1060    // and decrement and write back the result in the same file, if needed.
1061    LOG(INFO) << "Update check count = " << update_check_count_value;
1062
1063    if (update_check_count_value == 0) {
1064      // It could be 0, if, for some reason, the file didn't get deleted
1065      // when we set our status to waiting for reboot. so we just leave it
1066      // as is so that we can prevent another update_check wait for this client.
1067      LOG(INFO) << "Not decrementing update check count as it's already 0.";
1068      return true;
1069    }
1070
1071    if (update_check_count_value > 0)
1072      update_check_count_value--;
1073    else
1074      update_check_count_value = 0;
1075
1076    // Write out the new value of update_check_count_value.
1077    if (prefs_->SetInt64(kPrefsUpdateCheckCount, update_check_count_value)) {
1078      // We successfully wrote out te new value, so enable the
1079      // update check based wait.
1080      LOG(INFO) << "New update check count = " << update_check_count_value;
1081      return true;
1082    }
1083  }
1084
1085  LOG(INFO) << "Deleting update check count state due to read/write errors.";
1086
1087  // We cannot read/write to the file, so disable the update check based wait
1088  // so that we don't get stuck in this OS version by any chance (which could
1089  // happen if there's some bug that causes to read/write incorrectly).
1090  // Also attempt to delete the file to do our best effort to cleanup.
1091  prefs_->Delete(kPrefsUpdateCheckCount);
1092  return false;
1093}
1094
1095}  // namespace chromeos_update_engine
1096