Parse postinstall program progress updates.

In Android postinstall is expected to take a long time in common cases.
This patch allows the postinstall program to report back to the updater
a progress indication, which will then be forwarded to all the clients
listening. These progress updates are part of the FINALIZING status.

Bug: 27880754
TEST=Added unittests. Deployed an update to an edison-eng and post-install reported progress back with the postinstall_example.

Change-Id: I35f96b92f090219c54cca48d8ab07c54cf8b4ab1
diff --git a/payload_consumer/postinstall_runner_action.cc b/payload_consumer/postinstall_runner_action.cc
index 7fa7009..db1ec3c 100644
--- a/payload_consumer/postinstall_runner_action.cc
+++ b/payload_consumer/postinstall_runner_action.cc
@@ -16,15 +16,17 @@
 
 #include "update_engine/payload_consumer/postinstall_runner_action.h"
 
+#include <fcntl.h>
 #include <signal.h>
 #include <stdlib.h>
 #include <sys/mount.h>
 #include <sys/types.h>
-#include <vector>
+#include <unistd.h>
 
 #include <base/files/file_path.h>
 #include <base/files/file_util.h>
 #include <base/logging.h>
+#include <base/strings/string_split.h>
 #include <base/strings/string_util.h>
 
 #include "update_engine/common/action_processor.h"
@@ -33,8 +35,19 @@
 #include "update_engine/common/subprocess.h"
 #include "update_engine/common/utils.h"
 
+namespace {
+
+// The file descriptor number from the postinstall program's perspective where
+// it can report status updates. This can be any number greater than 2 (stderr),
+// but must be kept in sync with the "bin/postinst_progress" defined in the
+// sample_images.sh file.
+const int kPostinstallStatusFd = 3;
+
+}  // namespace
+
 namespace chromeos_update_engine {
 
+using brillo::MessageLoop;
 using std::string;
 using std::vector;
 
@@ -50,6 +63,19 @@
     }
   }
 
+  // Initialize all the partition weights.
+  partition_weight_.resize(install_plan_.partitions.size());
+  total_weight_ = 0;
+  for (size_t i = 0; i < install_plan_.partitions.size(); ++i) {
+    // TODO(deymo): This code sets the weight to all the postinstall commands,
+    // but we could remember how long they took in the past and use those
+    // values.
+    partition_weight_[i] = install_plan_.partitions[i].run_postinstall;
+    total_weight_ += partition_weight_[i];
+  }
+  accumulated_weight_ = 0;
+  ReportProgress(0);
+
   PerformPartitionPostinstall();
 }
 
@@ -127,19 +153,104 @@
 
   // Runs the postinstall script asynchronously to free up the main loop while
   // it's running.
-  vector<string> command = {abs_path, partition.target_path};
-  current_command_ = Subprocess::Get().Exec(
+  vector<string> command = {abs_path};
+#ifdef __ANDROID__
+  // In Brillo and Android, we pass the slot number and status fd.
+  command.push_back(std::to_string(install_plan_.target_slot));
+  command.push_back(std::to_string(kPostinstallStatusFd));
+#else
+  // Chrome OS postinstall expects the target rootfs as the first parameter.
+  command.push_back(partition.target_path);
+#endif  // __ANDROID__
+
+  current_command_ = Subprocess::Get().ExecFlags(
       command,
+      Subprocess::kRedirectStderrToStdout,
+      {kPostinstallStatusFd},
       base::Bind(&PostinstallRunnerAction::CompletePartitionPostinstall,
                  base::Unretained(this)));
   // Subprocess::Exec should never return a negative process id.
   CHECK_GE(current_command_, 0);
 
-  if (!current_command_)
+  if (!current_command_) {
     CompletePartitionPostinstall(1, "Postinstall didn't launch");
+    return;
+  }
+
+  // Monitor the status file descriptor.
+  progress_fd_ =
+      Subprocess::Get().GetPipeFd(current_command_, kPostinstallStatusFd);
+  int fd_flags = fcntl(progress_fd_, F_GETFL, 0) | O_NONBLOCK;
+  if (HANDLE_EINTR(fcntl(progress_fd_, F_SETFL, fd_flags)) < 0) {
+    PLOG(ERROR) << "Unable to set non-blocking I/O mode on fd " << progress_fd_;
+  }
+
+  progress_task_ = MessageLoop::current()->WatchFileDescriptor(
+      FROM_HERE,
+      progress_fd_,
+      MessageLoop::WatchMode::kWatchRead,
+      true,
+      base::Bind(&PostinstallRunnerAction::OnProgressFdReady,
+                 base::Unretained(this)));
 }
 
-void PostinstallRunnerAction::CleanupMount() {
+void PostinstallRunnerAction::OnProgressFdReady() {
+  char buf[1024];
+  size_t bytes_read;
+  do {
+    bytes_read = 0;
+    bool eof;
+    bool ok =
+        utils::ReadAll(progress_fd_, buf, arraysize(buf), &bytes_read, &eof);
+    progress_buffer_.append(buf, bytes_read);
+    // Process every line.
+    vector<string> lines = base::SplitString(
+        progress_buffer_, "\n", base::KEEP_WHITESPACE, base::SPLIT_WANT_ALL);
+    if (!lines.empty()) {
+      progress_buffer_ = lines.back();
+      lines.pop_back();
+      for (const auto& line : lines) {
+        ProcessProgressLine(line);
+      }
+    }
+    if (!ok || eof) {
+      // There was either an error or an EOF condition, so we are done watching
+      // the file descriptor.
+      MessageLoop::current()->CancelTask(progress_task_);
+      progress_task_ = MessageLoop::kTaskIdNull;
+      return;
+    }
+  } while (bytes_read);
+}
+
+bool PostinstallRunnerAction::ProcessProgressLine(const string& line) {
+  double frac = 0;
+  if (sscanf(line.c_str(), "global_progress %lf", &frac) == 1) {
+    ReportProgress(frac);
+    return true;
+  }
+
+  return false;
+}
+
+void PostinstallRunnerAction::ReportProgress(double frac) {
+  if (!delegate_)
+    return;
+  if (current_partition_ >= partition_weight_.size()) {
+    delegate_->ProgressUpdate(1.);
+    return;
+  }
+  if (!isfinite(frac) || frac < 0)
+    frac = 0;
+  if (frac > 1)
+    frac = 1;
+  double postinst_action_progress =
+      (accumulated_weight_ + partition_weight_[current_partition_] * frac) /
+      total_weight_;
+  delegate_->ProgressUpdate(postinst_action_progress);
+}
+
+void PostinstallRunnerAction::Cleanup() {
   utils::UnmountFilesystem(fs_mount_dir_);
 #ifndef __ANDROID__
   if (!base::DeleteFile(base::FilePath(fs_mount_dir_), false)) {
@@ -147,12 +258,19 @@
   }
 #endif  // !__ANDROID__
   fs_mount_dir_.clear();
+
+  progress_fd_ = -1;
+  if (progress_task_ != MessageLoop::kTaskIdNull) {
+    MessageLoop::current()->CancelTask(progress_task_);
+    progress_task_ = MessageLoop::kTaskIdNull;
+  }
+  progress_buffer_.clear();
 }
 
 void PostinstallRunnerAction::CompletePartitionPostinstall(
     int return_code, const string& output) {
   current_command_ = 0;
-  CleanupMount();
+  Cleanup();
 
   if (return_code != 0) {
     LOG(ERROR) << "Postinst command failed with code: " << return_code;
@@ -173,7 +291,10 @@
     }
     return CompletePostinstall(error_code);
   }
+  accumulated_weight_ += partition_weight_[current_partition_];
   current_partition_++;
+  ReportProgress(0);
+
   PerformPartitionPostinstall();
 }
 
@@ -227,7 +348,7 @@
   // the unretained reference to this object.
   Subprocess::Get().KillExec(current_command_);
   current_command_ = 0;
-  CleanupMount();
+  Cleanup();
 }
 
 }  // namespace chromeos_update_engine
diff --git a/payload_consumer/postinstall_runner_action.h b/payload_consumer/postinstall_runner_action.h
index a626ce6..4cdc47e 100644
--- a/payload_consumer/postinstall_runner_action.h
+++ b/payload_consumer/postinstall_runner_action.h
@@ -18,6 +18,10 @@
 #define UPDATE_ENGINE_PAYLOAD_CONSUMER_POSTINSTALL_RUNNER_ACTION_H_
 
 #include <string>
+#include <vector>
+
+#include <brillo/message_loops/message_loop.h>
+#include <gtest/gtest_prod.h>
 
 #include "update_engine/common/action.h"
 #include "update_engine/payload_consumer/install_plan.h"
@@ -40,12 +44,24 @@
   void ResumeAction() override;
   void TerminateProcessing() override;
 
+  class DelegateInterface {
+   public:
+    virtual ~DelegateInterface() = default;
+
+    // Called whenever there is an overall progress update from the postinstall
+    // programs.
+    virtual void ProgressUpdate(double progress) = 0;
+  };
+
+  void set_delegate(DelegateInterface* delegate) { delegate_ = delegate; }
+
   // Debugging/logging
   static std::string StaticType() { return "PostinstallRunnerAction"; }
   std::string Type() const override { return StaticType(); }
 
  private:
   friend class PostinstallRunnerActionTest;
+  FRIEND_TEST(PostinstallRunnerActionTest, ProcessProgressLineTest);
 
   // Special constructor used for testing purposes.
   PostinstallRunnerAction(BootControlInterface* boot_control,
@@ -55,8 +71,25 @@
 
   void PerformPartitionPostinstall();
 
-  // Unmount and remove the mountpoint directory if needed.
-  void CleanupMount();
+  // Called whenever the |progress_fd_| has data available to read.
+  void OnProgressFdReady();
+
+  // Updates the action progress according to the |line| passed from the
+  // postinstall program. Valid lines are:
+  //     global_progress <frac>
+  //         <frac> should be between 0.0 and 1.0; sets the progress to the
+  //         <frac> value.
+  bool ProcessProgressLine(const std::string& line);
+
+  // Report the progress to the delegate given that the postinstall operation
+  // for |current_partition_| has a current progress of |frac|, a value between
+  // 0 and 1 for that step.
+  void ReportProgress(double frac);
+
+  // Cleanup the setup made when running postinstall for a given partition.
+  // Unmount and remove the mountpoint directory if needed and cleanup the
+  // status file descriptor and message loop task watching for it.
+  void Cleanup();
 
   // Subprocess::Exec callback.
   void CompletePartitionPostinstall(int return_code,
@@ -75,6 +108,22 @@
   // InstallPlan.
   size_t current_partition_{0};
 
+  // A non-negative value representing the estimated weight of each partition
+  // passed in the install plan. The weight is used to predict the overall
+  // progress from the individual progress of each partition and should
+  // correspond to the time it takes to run it.
+  std::vector<double> partition_weight_;
+
+  // The sum of all the weights in |partition_weight_|.
+  double total_weight_{0};
+
+  // The sum of all the weights in |partition_weight_| up to but not including
+  // the |current_partition_|.
+  double accumulated_weight_{0};
+
+  // The delegate used to notify of progress updates, if any.
+  DelegateInterface* delegate_{nullptr};
+
   // The BootControlInerface used to mark the new slot as ready.
   BootControlInterface* boot_control_;
 
@@ -89,6 +138,14 @@
   // Postinstall command currently running, or 0 if no program running.
   pid_t current_command_{0};
 
+  // The parent progress file descriptor used to watch for progress reports from
+  // the postinstall program and the task watching for them.
+  int progress_fd_{-1};
+  brillo::MessageLoop::TaskId progress_task_{brillo::MessageLoop::kTaskIdNull};
+
+  // A buffer of a partial read line from the progress file descriptor.
+  std::string progress_buffer_;
+
   DISALLOW_COPY_AND_ASSIGN(PostinstallRunnerAction);
 };
 
diff --git a/payload_consumer/postinstall_runner_action_unittest.cc b/payload_consumer/postinstall_runner_action_unittest.cc
index 7d300eb..3e7d87a 100644
--- a/payload_consumer/postinstall_runner_action_unittest.cc
+++ b/payload_consumer/postinstall_runner_action_unittest.cc
@@ -32,6 +32,7 @@
 #include <brillo/bind_lambda.h>
 #include <brillo/message_loops/base_message_loop.h>
 #include <brillo/message_loops/message_loop_utils.h>
+#include <gmock/gmock.h>
 #include <gtest/gtest.h>
 
 #include "update_engine/common/constants.h"
@@ -74,6 +75,12 @@
   bool processing_stopped_called_{false};
 };
 
+class MockPostinstallRunnerActionDelegate
+    : public PostinstallRunnerAction::DelegateInterface {
+ public:
+  MOCK_METHOD1(ProgressUpdate, void(double progress));
+};
+
 class PostinstallRunnerActionTest : public ::testing::Test {
  protected:
   void SetUp() override {
@@ -160,7 +167,10 @@
   string postinstall_image_;
 
   FakeBootControl fake_boot_control_;
-  PostinstActionProcessorDelegate delegate_;
+  PostinstActionProcessorDelegate processor_delegate_;
+
+  // The PostinstallRunnerAction delegate receiving the progress updates.
+  PostinstallRunnerAction::DelegateInterface* setup_action_delegate_{nullptr};
 
   // A pointer to the posinstall_runner action and the processor.
   PostinstallRunnerAction* postinstall_action_{nullptr};
@@ -187,13 +197,14 @@
   PostinstallRunnerAction runner_action(&fake_boot_control_,
                                         powerwash_marker_file_.c_str());
   postinstall_action_ = &runner_action;
+  runner_action.set_delegate(setup_action_delegate_);
   BondActions(&feeder_action, &runner_action);
   ObjectCollectorAction<InstallPlan> collector_action;
   BondActions(&runner_action, &collector_action);
   processor.EnqueueAction(&feeder_action);
   processor.EnqueueAction(&runner_action);
   processor.EnqueueAction(&collector_action);
-  processor.set_delegate(&delegate_);
+  processor.set_delegate(&processor_delegate_);
 
   loop_.PostTask(FROM_HERE,
                  base::Bind([&processor] { processor.StartProcessing(); }));
@@ -201,21 +212,43 @@
   ASSERT_FALSE(processor.IsRunning());
   postinstall_action_ = nullptr;
   processor_ = nullptr;
-  EXPECT_TRUE(delegate_.processing_stopped_called_ ||
-              delegate_.processing_done_called_);
-  if (delegate_.processing_done_called_) {
+  EXPECT_TRUE(processor_delegate_.processing_stopped_called_ ||
+              processor_delegate_.processing_done_called_);
+  if (processor_delegate_.processing_done_called_) {
     // Sanity check that the code was set when the processor finishes.
-    EXPECT_TRUE(delegate_.code_set_);
+    EXPECT_TRUE(processor_delegate_.code_set_);
   }
 }
 
+TEST_F(PostinstallRunnerActionTest, ProcessProgressLineTest) {
+  PostinstallRunnerAction action(&fake_boot_control_,
+                                 powerwash_marker_file_.c_str());
+  testing::StrictMock<MockPostinstallRunnerActionDelegate> mock_delegate_;
+  action.set_delegate(&mock_delegate_);
+
+  action.current_partition_ = 1;
+  action.partition_weight_ = {1, 2, 5};
+  action.accumulated_weight_ = 1;
+  action.total_weight_ = 8;
+
+  // 50% of the second actions is 2/8 = 0.25 of the total.
+  EXPECT_CALL(mock_delegate_, ProgressUpdate(0.25));
+  action.ProcessProgressLine("global_progress 0.5");
+  testing::Mock::VerifyAndClearExpectations(&mock_delegate_);
+
+  // None of these should trigger a progress update.
+  action.ProcessProgressLine("foo_bar");
+  action.ProcessProgressLine("global_progress");
+  action.ProcessProgressLine("global_progress ");
+}
+
 // Test that postinstall succeeds in the simple case of running the default
 // /postinst command which only exits 0.
 TEST_F(PostinstallRunnerActionTest, RunAsRootSimpleTest) {
   ScopedLoopbackDeviceBinder loop(postinstall_image_, false, nullptr);
   RunPosinstallAction(loop.dev(), kPostinstallDefaultScript, false);
-  EXPECT_EQ(ErrorCode::kSuccess, delegate_.code_);
-  EXPECT_TRUE(delegate_.processing_done_called_);
+  EXPECT_EQ(ErrorCode::kSuccess, processor_delegate_.code_);
+  EXPECT_TRUE(processor_delegate_.processing_done_called_);
 
   // Since powerwash_required was false, this should not trigger a powerwash.
   EXPECT_FALSE(utils::FileExists(powerwash_marker_file_.c_str()));
@@ -224,14 +257,14 @@
 TEST_F(PostinstallRunnerActionTest, RunAsRootRunSymlinkFileTest) {
   ScopedLoopbackDeviceBinder loop(postinstall_image_, false, nullptr);
   RunPosinstallAction(loop.dev(), "bin/postinst_link", false);
-  EXPECT_EQ(ErrorCode::kSuccess, delegate_.code_);
+  EXPECT_EQ(ErrorCode::kSuccess, processor_delegate_.code_);
 }
 
 TEST_F(PostinstallRunnerActionTest, RunAsRootPowerwashRequiredTest) {
   ScopedLoopbackDeviceBinder loop(postinstall_image_, false, nullptr);
   // Run a simple postinstall program but requiring a powerwash.
   RunPosinstallAction(loop.dev(), "bin/postinst_example", true);
-  EXPECT_EQ(ErrorCode::kSuccess, delegate_.code_);
+  EXPECT_EQ(ErrorCode::kSuccess, processor_delegate_.code_);
 
   // Check that the powerwash marker file was set.
   string actual_cmd;
@@ -244,7 +277,7 @@
 // fail.
 TEST_F(PostinstallRunnerActionTest, RunAsRootCantMountTest) {
   RunPosinstallAction("/dev/null", kPostinstallDefaultScript, false);
-  EXPECT_EQ(ErrorCode::kPostinstallRunnerError, delegate_.code_);
+  EXPECT_EQ(ErrorCode::kPostinstallRunnerError, processor_delegate_.code_);
 
   // In case of failure, Postinstall should not signal a powerwash even if it
   // was requested.
@@ -256,7 +289,7 @@
 TEST_F(PostinstallRunnerActionTest, RunAsRootErrScriptTest) {
   ScopedLoopbackDeviceBinder loop(postinstall_image_, false, nullptr);
   RunPosinstallAction(loop.dev(), "bin/postinst_fail1", false);
-  EXPECT_EQ(ErrorCode::kPostinstallRunnerError, delegate_.code_);
+  EXPECT_EQ(ErrorCode::kPostinstallRunnerError, processor_delegate_.code_);
 }
 
 // The exit code 3 and 4 are a specials cases that would be reported back to
@@ -264,14 +297,15 @@
 TEST_F(PostinstallRunnerActionTest, RunAsRootFirmwareBErrScriptTest) {
   ScopedLoopbackDeviceBinder loop(postinstall_image_, false, nullptr);
   RunPosinstallAction(loop.dev(), "bin/postinst_fail3", false);
-  EXPECT_EQ(ErrorCode::kPostinstallBootedFromFirmwareB, delegate_.code_);
+  EXPECT_EQ(ErrorCode::kPostinstallBootedFromFirmwareB,
+            processor_delegate_.code_);
 }
 
 // Check that you can't specify an absolute path.
 TEST_F(PostinstallRunnerActionTest, RunAsRootAbsolutePathNotAllowedTest) {
   ScopedLoopbackDeviceBinder loop(postinstall_image_, false, nullptr);
   RunPosinstallAction(loop.dev(), "/etc/../bin/sh", false);
-  EXPECT_EQ(ErrorCode::kPostinstallRunnerError, delegate_.code_);
+  EXPECT_EQ(ErrorCode::kPostinstallRunnerError, processor_delegate_.code_);
 }
 
 #ifdef __ANDROID__
@@ -280,7 +314,7 @@
 TEST_F(PostinstallRunnerActionTest, RunAsRootCheckFileContextsTest) {
   ScopedLoopbackDeviceBinder loop(postinstall_image_, false, nullptr);
   RunPosinstallAction(loop.dev(), "bin/self_check_context", false);
-  EXPECT_EQ(ErrorCode::kSuccess, delegate_.code_);
+  EXPECT_EQ(ErrorCode::kSuccess, processor_delegate_.code_);
 }
 #endif  // __ANDROID__
 
@@ -294,8 +328,8 @@
                             base::Unretained(this)));
   RunPosinstallAction(loop.dev(), "bin/postinst_suspend", false);
   // postinst_suspend returns 0 only if it was suspended at some point.
-  EXPECT_EQ(ErrorCode::kSuccess, delegate_.code_);
-  EXPECT_TRUE(delegate_.processing_done_called_);
+  EXPECT_EQ(ErrorCode::kSuccess, processor_delegate_.code_);
+  EXPECT_TRUE(processor_delegate_.processing_done_called_);
 }
 
 // Test that we can cancel a postinstall action while it is running.
@@ -307,8 +341,28 @@
   RunPosinstallAction(loop.dev(), "bin/postinst_suspend", false);
   // When canceling the action, the action never finished and therefore we had
   // a ProcessingStopped call instead.
-  EXPECT_FALSE(delegate_.code_set_);
-  EXPECT_TRUE(delegate_.processing_stopped_called_);
+  EXPECT_FALSE(processor_delegate_.code_set_);
+  EXPECT_TRUE(processor_delegate_.processing_stopped_called_);
+}
+
+// Test that we parse and process the progress reports from the progress
+// file descriptor.
+TEST_F(PostinstallRunnerActionTest, RunAsRootProgressUpdatesTest) {
+  testing::StrictMock<MockPostinstallRunnerActionDelegate> mock_delegate_;
+  testing::InSequence s;
+  EXPECT_CALL(mock_delegate_, ProgressUpdate(0));
+
+  // The postinst_progress program will call with 0.25, 0.5 and 1.
+  EXPECT_CALL(mock_delegate_, ProgressUpdate(0.25));
+  EXPECT_CALL(mock_delegate_, ProgressUpdate(0.5));
+  EXPECT_CALL(mock_delegate_, ProgressUpdate(1.));
+
+  EXPECT_CALL(mock_delegate_, ProgressUpdate(1.));
+
+  ScopedLoopbackDeviceBinder loop(postinstall_image_, false, nullptr);
+  setup_action_delegate_ = &mock_delegate_;
+  RunPosinstallAction(loop.dev(), "bin/postinst_progress", false);
+  EXPECT_EQ(ErrorCode::kSuccess, processor_delegate_.code_);
 }
 
 }  // namespace chromeos_update_engine