[watchman] add integration test for the trigger command

Summary:
add a test for the "trigger" command, which is used
to spawn a process and invoke it when files that match a pattern
are observed to change.

This builds on the debug connection from the prior diff to
get its stuff done, and introduces a couple of nice helpers
functions that reduce flaky results without too many arbitrary
pauses.

Test Plan:
`arc unit`.
Note that there is a race in basic.php that can trigger if
we get multiple notifies about the file that we touch; these
can cause the cursor to return an additional file at the point
where we expect it to usually return none.

Reviewers: keegancsmith, dsereni, zoel, pieter

Reviewed By: zoel

Differential Revision: https://phabricator.fb.com/D648760

arcanist/lib/WatchmanInstance.php

@@ -20,13 +20,12 @@
 // for integration tests.
 // Ensures that it is terminated when it is destroyed.
 class WatchmanInstance {
-  private $dir;
   private $logfile;
   private $sockname;
-  private $invocations = 0;
   private $debug = false;
   private $sock;
   static $singleton = null;
+  private $logdata = array();
 
   static function get() {
     if (!self::$singleton) {
@@ -36,75 +35,98 @@ static function get() {
   }
 
   function __construct() {
-    $this->dir = realpath(dirname(__FILE__) . '/../../tests/integration');
-    $this->logfile = $this->dir . "/.watchman.log";
-    $this->sockname = $this->dir . "/.watchman.sock";
+    $this->logfile = new TempFile();
+    $this->sockname = new TempFile();
   }
 
   function setDebug($enable) {
     $this->debug = $enable;
   }
 
-  function command() {
-    $args = func_get_args();
+  protected function readResponses() {
+    do {
+      $data = fgets($this->sock);
+      if ($data === false) return;
+      $resp = json_decode($data, true);
+      if (!isset($resp['log'])) {
+        return $resp;
+      }
+      // Collect log information
+      $this->logdata[] = $resp['log'];
+    } while (true);
+  }
 
-    if (count($args)) {
-      $args = array(
-        "./watchman --sockname=%s --logfile=%s %Ls",
-        $this->sockname,
-        $this->logfile,
-        $args);
-    } else {
-      $args = array(
-        "./watchman --sockname=%s --logfile=%s",
-        $this->sockname,
-        $this->logfile);
+  function setLogLevel($level) {
+    return $this->request('log-level', $level);
+  }
+
+  function waitForLog($criteria, $timeout = 5) {
+    foreach ($this->logdata as $line) {
+      $matches = array();
+      if (preg_match($criteria, $line, $matches)) {
+        return array(true, $line, $matches);
+      }
     }
 
-    $this->invocations++;
+    $deadline = time() + $timeout;
+    while (time() < $deadline) {
+      stream_set_timeout($this->sock, $deadline - time());
+      $data = fgets($this->sock);
+      stream_set_timeout($this->sock, 60);
+
+      if ($data === false) {
+        break;
+      }
+      $resp = json_decode($data, true);
+      if (!isset($resp['log'])) {
+        throw new Exception("expected a log response, got $data");
+      }
+      $this->logdata[] = $resp['log'];
+
+      if (preg_match($criteria, $resp['log'], $matches)) {
+        return array(true, $resp['log'], $matches);
+      }
+    }
+    return array(false, null, null);
+  }
+
+  function start() {
+    $f = new ExecFuture(
+        "./watchman --sockname=%s.sock --logfile=%s",
+        $this->sockname,
+        $this->logfile);
+    $f->resolve();
 
-    return newv('ExecFuture', $args);
+    $this->sock = fsockopen('unix://' . $this->sockname . '.sock');
+    stream_set_timeout($this->sock, 60);
   }
 
   function request() {
     $args = func_get_args();
 
-    if (!$this->invocations) {
-      return call_user_func_array(
-        array($this, 'resolveCommand'),
-        $args);
-    }
-
-    // Use a socket instead
     if (!$this->sock) {
-      $this->sock = fsockopen('unix://' . $this->sockname);
+      $this->start();
     }
 
-    fwrite($this->sock, json_encode($args) . "\n");
-    $data = fgets($this->sock);
-    return json_decode($data, true);
-  }
-
-  function resolveCommand() {
-    $args = func_get_args();
-
-    $future = call_user_func_array(
-      array($this, 'command'),
-      $args);
+    if (!count($args)) {
+      // No command to send right now (we're just warming up)
+      return true;
+    }
 
+    $req = json_encode($args);
     if ($this->debug) {
-      echo "running: " . $future->getCommand() . "\n";
-    }
-    if (count($args)) {
-      return $future->resolveJSON();
+      echo "Sending $req\n";
     }
-    return $future->resolvex();
+    fwrite($this->sock, $req . "\n");
+    return $this->readResponses();
   }
 
   function __destruct() {
-    if ($this->invocations) {
-      $future = $this->command('shutdown-server');
-      $future->resolve();
+    if ($this->sock) {
+      $this->request('shutdown-server');
+      if ($this->debug) {
+        echo implode("", $this->logdata);
+      }
     }
   }
 

arcanist/lib/WatchmanTestCase.php

@@ -47,6 +47,68 @@ function assertRegex($pattern, $subject, $message = null) {
     }
   }
 
+  function setLogLevel($level) {
+    $out = WatchmanInstance::get()->setLogLevel($level);
+    $this->assertEqual($level, $out['log_level'], "set log level to $level");
+  }
+
+  function waitForLog($criteria, $timeout = 5) {
+    // Can't use the generic waitFor routine here because
+    // we're delegating to a more efficient mechanism in
+    // the instance class.
+    return WatchmanInstance::get()->waitForLog($criteria, $timeout);
+  }
+
+  function assertWaitForLog($criteria, $timeout = 5) {
+    list($ok, $line, $matches) = $this->waitForLog($criteria, $timeout);
+    if (!$ok) {
+      $this->assertFailure(
+        "did not find $critiera in log output within $timeout seconds");
+    }
+    return array($ok, $line, $matches);
+  }
+
+  // Generic waiting assertion; continually invokes $callable
+  // until timeout is hit.  Returns the returned value from
+  // $callable if it is truthy.
+  // Asserts failure if no truthy value is encountered within
+  // the timeout
+  function waitFor($callable, $timeout = 10, $message = null) {
+    $deadline = time() + $timeout;
+    while (time() <= $deadline) {
+      $res = $callable();
+      if ($res) {
+        return $res;
+      }
+      usleep(30000);
+    }
+    if ($message === null) {
+      $message = "Condition [$callable] was not met in $timeout seconds";
+    }
+    $this->assertFailure($message);
+  }
+
+  // Wait for a watchman command to return output that matches
+  // some criteria.
+  // Returns the command output.
+  // $have_data is a callable that returns a boolean result
+  // to indicate that the criteria have been met.
+  // timeout is the timeout in seconds.
+  function waitForWatchman(array $command, $have_data, $timeout = 10) {
+    return $this->waitFor(
+      function () use ($command, $have_data) {
+        $out = call_user_func_array(
+          array(WatchmanInstance::get(), 'request'),
+          $command);
+        if ($have_data($out)) {
+          return $out;
+        }
+        return false;
+      },
+      $timeout,
+      "watchman $command didn't yield results within $timeout seconds"
+    );
+  }
 }
 
 

listener.c

@@ -693,7 +693,6 @@ static void *client_thread(void *ptr)
   char buf[16];
   int n;
 
-  w_set_nonblock(client->ping[0]);
   w_set_nonblock(client->fd);
 
   while (true) {
@@ -709,7 +708,7 @@ static void *client_thread(void *ptr)
     pfd[1].events = POLLIN|POLLHUP|POLLERR;
     pfd[1].revents = 0;
 
-    n = poll(pfd, 2, -1);
+    n = poll(pfd, 2, 200);
 
     if (pfd[0].revents) {
       request = w_json_reader_next(&client->reader, client->fd, &jerr);
@@ -780,6 +779,8 @@ static void *client_thread(void *ptr)
         json_decref(resp->json);
         free(resp);
 
+        w_set_nonblock(client->fd);
+
       }
     }
   }
@@ -885,7 +886,9 @@ bool w_start_listener(const char *path)
     }
     pipe(client->ping);
     w_set_cloexec(client->ping[0]);
+    w_set_nonblock(client->ping[0]);
     w_set_cloexec(client->ping[1]);
+    w_set_nonblock(client->ping[1]);
 
     pthread_mutex_lock(&client_lock);
     w_ht_set(clients, client->fd, (w_ht_val_t)client);

log.c

@@ -22,8 +22,9 @@ void w_log(int level, const char *fmt, ...)
   va_list ap;
   int len;
 
+  len = snprintf(buf, sizeof(buf), "%d: ", (int)time(NULL));
   va_start(ap, fmt);
-  len = vsnprintf(buf, sizeof(buf), fmt, ap);
+  len += vsnprintf(buf + len, sizeof(buf), fmt, ap);
   va_end(ap);
 
   write(STDERR_FILENO, buf, len);

root.c

@@ -402,9 +402,7 @@ static void stat_path(w_root_t *root,
     if (!file) {
       file = w_root_resolve_file(root, dir, file_name);
     }
-    if (memcmp(&file->st, &st, sizeof(st))) {
-      w_root_mark_file_changed(root, file, now, confident);
-    }
+    w_root_mark_file_changed(root, file, now, confident);
     memcpy(&file->st, &st, sizeof(st));
   } else if (S_ISDIR(st.st_mode)) {
     if (!dir_ent) {

tests/integration/basic.php

@@ -29,16 +29,24 @@ function testFind() {
     $this->assertEqual($root, $out['watch']);
 
     // Allow time for the files to be found
-    for ($tries = 0; $tries < 20; $tries++) {
-      $out = $this->watchmanCommand('find', $root, '*.c');
-      if (count($out['files'])) {
-        break;
+    $out = $this->waitForWatchman(
+      array('find', $root),
+      function ($out) {
+        return count($out['files']) == 2;
       }
-      usleep(2000);
-    }
+    );
 
-    $this->assertEqual('foo.c', $out['files'][0]['name']);
-    $this->assertEqual(1, count($out['files']), 'only one match');
+    asort($out['files']);
+    $this->assertEqual(array(
+      array(
+        'name' => 'bar.txt',
+        'exists' => true
+      ),
+      array(
+        'name' => 'foo.c',
+        'exists' => true
+      ),
+    ), $out['files']);
   }
 
   function testCursor() {
@@ -55,14 +63,13 @@ function testCursor() {
     touch($root . '/one');
 
     // Allow time for the change to be observed
-    for ($tries = 0; $tries < 20; $tries++) {
-      $update = $this->watchmanCommand('since', $root,
-        'n:testCursor');
-      if (count($update['files'])) {
-        break;
+    $update = $this->waitForWatchman(
+      array('since', $root, 'n:testCursor'),
+      function ($update) {
+        return count($update['files']);
       }
-      usleep(30000);
-    }
+    );
+
     $this->assertEqual('one',
       $update['files'][0]['name'], 'saw file change');
 

tests/integration/trig.sh

@@ -0,0 +1,12 @@
+#!/bin/sh
+# $1 = name of a log file
+# the rest of the args are names of files that were modified
+log="$1"
+shift
+
+date +%s >>$log 
+while test -n "$1" ; do
+  echo >>$log $1
+  shift
+done
+