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