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