Merge pull request #1281 from colincross/rebuild_on_error

Rebuild edges that update their output file on error

9 files changed, 106 insertions, 30 deletions

diff --git a/src/build.cc b/src/build.cc
index a0c7ec8..1cce981 100644
--- a/src/build.cc
+++ b/src/build.cc
@@ -275,6 +275,13 @@ void BuildStatus::PrintStatus(Edge* edge, EdgeStatus status) {
 
 Plan::Plan() : command_edges_(0), wanted_edges_(0) {}
 
+void Plan::Reset() {
+  command_edges_ = 0;
+  wanted_edges_ = 0;
+  ready_.clear();
+  want_.clear();
+}
+
 bool Plan::AddTarget(Node* node, string* err) {
   vector<Node*> stack;
   return AddSubTarget(node, &stack, err);
@@ -793,9 +800,10 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) {
     return true;
   }
 
-  // Restat the edge outputs, if necessary.
-  TimeStamp restat_mtime = 0;
-  if (edge->GetBindingBool("restat") && !config_.dry_run) {
+  // Restat the edge outputs
+  TimeStamp output_mtime = 0;
+  bool restat = edge->GetBindingBool("restat");
+  if (!config_.dry_run) {
     bool node_cleaned = false;
 
     for (vector<Node*>::iterator o = edge->outputs_.begin();
@@ -803,7 +811,9 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) {
       TimeStamp new_mtime = disk_interface_->Stat((*o)->path(), err);
       if (new_mtime == -1)
         return false;
-      if ((*o)->mtime() == new_mtime) {
+      if (new_mtime > output_mtime)
+        output_mtime = new_mtime;
+      if ((*o)->mtime() == new_mtime && restat) {
         // The rule command did not change the output.  Propagate the clean
         // state through the build graph.
         // Note that this also applies to nonexistent outputs (mtime == 0).
@@ -814,6 +824,7 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) {
     }
 
     if (node_cleaned) {
+      TimeStamp restat_mtime = 0;
       // If any output was cleaned, find the most recent mtime of any
       // (existing) non-order-only input or the depfile.
       for (vector<Node*>::iterator i = edge->inputs_.begin();
@@ -837,6 +848,8 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) {
       // The total number of edges in the plan may have changed as a result
       // of a restat.
       status_->PlanHasTotalEdges(plan_.command_edge_count());
+
+      output_mtime = restat_mtime;
     }
   }
 
@@ -849,7 +862,7 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) {
 
   if (scan_.build_log()) {
     if (!scan_.build_log()->RecordCommand(edge, start_time, end_time,
-                                          restat_mtime)) {
+                                          output_mtime)) {
       *err = string("Error writing to build log: ") + strerror(errno);
       return false;
     }
diff --git a/src/build.h b/src/build.h
index 66ce607..f97d67e 100644
--- a/src/build.h
+++ b/src/build.h
@@ -71,6 +71,9 @@ struct Plan {
   /// Number of edges with commands to run.
   int command_edge_count() const { return command_edges_; }
 
+  /// Reset state.  Clears want and ready sets.
+  void Reset();
+
 private:
   bool AddSubTarget(Node* node, vector<Node*>* stack, string* err);
   bool CheckDependencyCycle(Node* node, const vector<Node*>& stack,
diff --git a/src/build_log.cc b/src/build_log.cc
index 8a52514..333915a 100644
--- a/src/build_log.cc
+++ b/src/build_log.cc
@@ -105,7 +105,7 @@ BuildLog::LogEntry::LogEntry(const string& output)
 BuildLog::LogEntry::LogEntry(const string& output, uint64_t command_hash,
   int start_time, int end_time, TimeStamp restat_mtime)
   : output(output), command_hash(command_hash),
-    start_time(start_time), end_time(end_time), restat_mtime(restat_mtime)
+    start_time(start_time), end_time(end_time), mtime(restat_mtime)
 {}
 
 BuildLog::BuildLog()
@@ -145,7 +145,7 @@ bool BuildLog::OpenForWrite(const string& path, const BuildLogUser& user,
 }
 
 bool BuildLog::RecordCommand(Edge* edge, int start_time, int end_time,
-                             TimeStamp restat_mtime) {
+                             TimeStamp mtime) {
   string command = edge->EvaluateCommand(true);
   uint64_t command_hash = LogEntry::HashCommand(command);
   for (vector<Node*>::iterator out = edge->outputs_.begin();
@@ -162,7 +162,7 @@ bool BuildLog::RecordCommand(Edge* edge, int start_time, int end_time,
     log_entry->command_hash = command_hash;
     log_entry->start_time = start_time;
     log_entry->end_time = end_time;
-    log_entry->restat_mtime = restat_mtime;
+    log_entry->mtime = mtime;
 
     if (log_file_) {
       if (!WriteEntry(log_file_, *log_entry))
@@ -314,7 +314,7 @@ bool BuildLog::Load(const string& path, string* err) {
 
     entry->start_time = start_time;
     entry->end_time = end_time;
-    entry->restat_mtime = restat_mtime;
+    entry->mtime = restat_mtime;
     if (log_version >= 5) {
       char c = *end; *end = '\0';
       entry->command_hash = (uint64_t)strtoull(start, NULL, 16);
@@ -354,7 +354,7 @@ BuildLog::LogEntry* BuildLog::LookupByOutput(const string& path) {
 
 bool BuildLog::WriteEntry(FILE* f, const LogEntry& entry) {
   return fprintf(f, "%d\t%d\t%d\t%s\t%" PRIx64 "\n",
-          entry.start_time, entry.end_time, entry.restat_mtime,
+          entry.start_time, entry.end_time, entry.mtime,
           entry.output.c_str(), entry.command_hash) > 0;
 }
 
diff --git a/src/build_log.h b/src/build_log.h
index 785961e..5268fab 100644
--- a/src/build_log.h
+++ b/src/build_log.h
@@ -45,7 +45,7 @@ struct BuildLog {
 
   bool OpenForWrite(const string& path, const BuildLogUser& user, string* err);
   bool RecordCommand(Edge* edge, int start_time, int end_time,
-                     TimeStamp restat_mtime = 0);
+                     TimeStamp mtime = 0);
   void Close();
 
   /// Load the on-disk log.
@@ -56,7 +56,7 @@ struct BuildLog {
     uint64_t command_hash;
     int start_time;
     int end_time;
-    TimeStamp restat_mtime;
+    TimeStamp mtime;
 
     static uint64_t HashCommand(StringPiece command);
 
@@ -64,7 +64,7 @@ struct BuildLog {
     bool operator==(const LogEntry& o) {
       return output == o.output && command_hash == o.command_hash &&
           start_time == o.start_time && end_time == o.end_time &&
-          restat_mtime == o.restat_mtime;
+          mtime == o.mtime;
     }
 
     explicit LogEntry(const string& output);
diff --git a/src/build_log_perftest.cc b/src/build_log_perftest.cc
index 185c512..b4efb1d 100644
--- a/src/build_log_perftest.cc
+++ b/src/build_log_perftest.cc
@@ -92,7 +92,7 @@ bool WriteTestData(string* err) {
     log.RecordCommand(state.edges_[i],
                       /*start_time=*/100 * i,
                       /*end_time=*/100 * i + 1,
-                      /*restat_mtime=*/0);
+                      /*mtime=*/0);
   }
 
   return true;
diff --git a/src/build_log_test.cc b/src/build_log_test.cc
index f4c9044..ad30380 100644
--- a/src/build_log_test.cc
+++ b/src/build_log_test.cc
@@ -181,7 +181,7 @@ TEST_F(BuildLogTest, SpacesInOutputV4) {
   ASSERT_TRUE(e);
   ASSERT_EQ(123, e->start_time);
   ASSERT_EQ(456, e->end_time);
-  ASSERT_EQ(456, e->restat_mtime);
+  ASSERT_EQ(456, e->mtime);
   ASSERT_NO_FATAL_FAILURE(AssertHash("command", e->command_hash));
 }
 
@@ -205,14 +205,14 @@ TEST_F(BuildLogTest, DuplicateVersionHeader) {
   ASSERT_TRUE(e);
   ASSERT_EQ(123, e->start_time);
   ASSERT_EQ(456, e->end_time);
-  ASSERT_EQ(456, e->restat_mtime);
+  ASSERT_EQ(456, e->mtime);
   ASSERT_NO_FATAL_FAILURE(AssertHash("command", e->command_hash));
 
   e = log.LookupByOutput("out2");
   ASSERT_TRUE(e);
   ASSERT_EQ(456, e->start_time);
   ASSERT_EQ(789, e->end_time);
-  ASSERT_EQ(789, e->restat_mtime);
+  ASSERT_EQ(789, e->mtime);
   ASSERT_NO_FATAL_FAILURE(AssertHash("command2", e->command_hash));
 }
 
@@ -240,7 +240,7 @@ TEST_F(BuildLogTest, VeryLongInputLine) {
   ASSERT_TRUE(e);
   ASSERT_EQ(456, e->start_time);
   ASSERT_EQ(789, e->end_time);
-  ASSERT_EQ(789, e->restat_mtime);
+  ASSERT_EQ(789, e->mtime);
   ASSERT_NO_FATAL_FAILURE(AssertHash("command2", e->command_hash));
 }
 
diff --git a/src/build_test.cc b/src/build_test.cc
index 640e1b0..0eb9aaa 100644
--- a/src/build_test.cc
+++ b/src/build_test.cc
@@ -608,7 +608,8 @@ bool FakeCommandRunner::StartCommand(Edge* edge) {
       edge->rule().name() == "cat_rsp_out" ||
       edge->rule().name() == "cc" ||
       edge->rule().name() == "touch" ||
-      edge->rule().name() == "touch-interrupt") {
+      edge->rule().name() == "touch-interrupt" ||
+      edge->rule().name() == "touch-fail-tick2") {
     for (vector<Node*>::iterator out = edge->outputs_.begin();
          out != edge->outputs_.end(); ++out) {
       fs_->Create((*out)->path(), "");
@@ -649,7 +650,8 @@ bool FakeCommandRunner::WaitForCommand(Result* result) {
     return true;
   }
 
-  if (edge->rule().name() == "fail")
+  if (edge->rule().name() == "fail" ||
+      (edge->rule().name() == "touch-fail-tick2" && fs_->now_ == 2))
     result->status = ExitFailure;
   else
     result->status = ExitSuccess;
@@ -1258,6 +1260,51 @@ TEST_F(BuildWithLogTest, NotInLogButOnDisk) {
   EXPECT_TRUE(builder_.AlreadyUpToDate());
 }
 
+TEST_F(BuildWithLogTest, RebuildAfterFailure) {
+  ASSERT_NO_FATAL_FAILURE(AssertParse(&state_,
+"rule touch-fail-tick2\n"
+"  command = touch-fail-tick2\n"
+"build out1: touch-fail-tick2 in\n"));
+
+  string err;
+
+  fs_.Create("in", "");
+
+  // Run once successfully to get out1 in the log
+  EXPECT_TRUE(builder_.AddTarget("out1", &err));
+  EXPECT_TRUE(builder_.Build(&err));
+  EXPECT_EQ("", err);
+  EXPECT_EQ(1u, command_runner_.commands_ran_.size());
+
+  command_runner_.commands_ran_.clear();
+  state_.Reset();
+  builder_.Cleanup();
+  builder_.plan_.Reset();
+
+  fs_.Tick();
+  fs_.Create("in", "");
+
+  // Run again with a failure that updates the output file timestamp
+  EXPECT_TRUE(builder_.AddTarget("out1", &err));
+  EXPECT_FALSE(builder_.Build(&err));
+  EXPECT_EQ("subcommand failed", err);
+  EXPECT_EQ(1u, command_runner_.commands_ran_.size());
+
+  command_runner_.commands_ran_.clear();
+  state_.Reset();
+  builder_.Cleanup();
+  builder_.plan_.Reset();
+
+  fs_.Tick();
+
+  // Run again, should rerun even though the output file is up to date on disk
+  EXPECT_TRUE(builder_.AddTarget("out1", &err));
+  EXPECT_FALSE(builder_.AlreadyUpToDate());
+  EXPECT_TRUE(builder_.Build(&err));
+  EXPECT_EQ(1u, command_runner_.commands_ran_.size());
+  EXPECT_EQ("", err);
+}
+
 TEST_F(BuildWithLogTest, RestatTest) {
   ASSERT_NO_FATAL_FAILURE(AssertParse(&state_,
 "rule true\n"
@@ -1438,7 +1485,7 @@ TEST_F(BuildWithLogTest, RestatMissingInput) {
   // the right mtime
   BuildLog::LogEntry* log_entry = build_log_.LookupByOutput("out1");
   ASSERT_TRUE(NULL != log_entry);
-  ASSERT_EQ(restat_mtime, log_entry->restat_mtime);
+  ASSERT_EQ(restat_mtime, log_entry->mtime);
 
   // Now remove a file, referenced from depfile, so that target becomes
   // dirty, but the output does not change
@@ -1455,7 +1502,7 @@ TEST_F(BuildWithLogTest, RestatMissingInput) {
   // Check that the logfile entry remains correctly set
   log_entry = build_log_.LookupByOutput("out1");
   ASSERT_TRUE(NULL != log_entry);
-  ASSERT_EQ(restat_mtime, log_entry->restat_mtime);
+  ASSERT_EQ(restat_mtime, log_entry->mtime);
 }
 
 struct BuildDryRun : public BuildWithLogTest {
diff --git a/src/disk_interface.cc b/src/disk_interface.cc
index 1b4135f..b418e04 100644
--- a/src/disk_interface.cc
+++ b/src/disk_interface.cc
@@ -28,6 +28,7 @@
 #include <direct.h>  // _mkdir
 #endif
 
+#include "metrics.h"
 #include "util.h"
 
 namespace {
@@ -148,6 +149,7 @@ bool DiskInterface::MakeDirs(const string& path) {
 // RealDiskInterface -----------------------------------------------------------
 
 TimeStamp RealDiskInterface::Stat(const string& path, string* err) const {
+  METRIC_RECORD("node stat");
 #ifdef _WIN32
   // MSDN: "Naming Files, Paths, and Namespaces"
   // http://msdn.microsoft.com/en-us/library/windows/desktop/aa365247(v=vs.85).aspx
diff --git a/src/graph.cc b/src/graph.cc
index b4c8619..27013d5 100644
--- a/src/graph.cc
+++ b/src/graph.cc
@@ -28,7 +28,6 @@
 #include "util.h"
 
 bool Node::Stat(DiskInterface* disk_interface, string* err) {
-  METRIC_RECORD("node stat");
   return (mtime_ = disk_interface->Stat(path_, err)) != -1;
 }
 
@@ -169,7 +168,7 @@ bool DependencyScan::RecomputeOutputDirty(Edge* edge,
     bool used_restat = false;
     if (edge->GetBindingBool("restat") && build_log() &&
         (entry = build_log()->LookupByOutput(output->path()))) {
-      output_mtime = entry->restat_mtime;
+      output_mtime = entry->mtime;
       used_restat = true;
     }
 
@@ -183,17 +182,29 @@ bool DependencyScan::RecomputeOutputDirty(Edge* edge,
     }
   }
 
-  // May also be dirty due to the command changing since the last build.
-  // But if this is a generator rule, the command changing does not make us
-  // dirty.
-  if (!edge->GetBindingBool("generator") && build_log()) {
+  if (build_log()) {
+    bool generator = edge->GetBindingBool("generator");
     if (entry || (entry = build_log()->LookupByOutput(output->path()))) {
-      if (BuildLog::LogEntry::HashCommand(command) != entry->command_hash) {
+      if (!generator &&
+          BuildLog::LogEntry::HashCommand(command) != entry->command_hash) {
+        // May also be dirty due to the command changing since the last build.
+        // But if this is a generator rule, the command changing does not make us
+        // dirty.
         EXPLAIN("command line changed for %s", output->path().c_str());
         return true;
       }
+      if (entry->mtime < most_recent_input->mtime()) {
+        // May also be dirty due to the mtime in the log being older than the
+        // mtime of the most recent input.  This can occur even when the mtime
+        // on disk is newer if a previous run wrote to the output file but
+        // exited with an error or was interrupted.
+        EXPLAIN("recorded mtime of %s older than most recent input %s (%d vs %d)",
+                output->path().c_str(), most_recent_input->path().c_str(),
+                entry->mtime, most_recent_input->mtime());
+        return true;
+      }
     }
-    if (!entry) {
+    if (!entry && !generator) {
       EXPLAIN("command line not found in log for %s", output->path().c_str());
       return true;
     }