Improve logging

Adds a human readable timestamp with millisecond granularity, and
thread names instead of the tid.

Adds some more context to some logs, and removes the noisy trigger
and subscription assessment logs.

cmds/subscribe.c

@@ -45,23 +45,25 @@ static json_t *build_subscription_results(
   struct w_clockspec *since_spec = sub->query->since_spec;
 
   if (since_spec && since_spec->tag == w_cs_clock) {
-    w_log(W_LOG_DBG, "running subscription rules! since %" PRIu32 "\n",
-        since_spec->clock.ticks);
+    w_log(W_LOG_DBG, "running subscription %s rules since %" PRIu32 "\n",
+        sub->name->buf, since_spec->clock.ticks);
   } else {
-    w_log(W_LOG_DBG, "running subscription rules!\n");
+    w_log(W_LOG_DBG, "running subscription %s rules (no since)\n",
+        sub->name->buf);
   }
 
   // Subscriptions never need to sync explicitly; we are only dispatched
   // at settle points which are by definition sync'd to the present time
   sub->query->sync_timeout = 0;
   if (!w_query_execute(sub->query, root, &res, subscription_generator, sub)) {
-    w_log(W_LOG_ERR, "error running subscription query: %s", res.errmsg);
+    w_log(W_LOG_ERR, "error running subscription %s query: %s",
+        sub->name->buf, res.errmsg);
     w_query_result_free(&res);
     return NULL;
   }
 
-  w_log(W_LOG_DBG, "subscription generated %" PRIu32 " results\n",
-      res.num_results);
+  w_log(W_LOG_DBG, "subscription %s generated %" PRIu32 " results\n",
+      sub->name->buf, res.num_results);
 
   if (res.num_results == 0) {
     w_query_result_free(&res);

listener.c

@@ -421,6 +421,7 @@ static void *client_thread(void *ptr)
   char buf[16];
 
   w_set_nonblock(client->fd);
+  w_set_thread_name("client:fd=%d", client->fd);
 
   while (!stopping) {
     // Wait for input from either the client socket or
@@ -552,6 +553,8 @@ static void *child_reaper(void *arg)
   sigset_t sigset;
   unused_parameter(arg);
 
+  w_set_thread_name("child_reaper");
+
   // Unblock SIGCHLD only in this thread
   sigemptyset(&sigset);
   sigaddset(&sigset, SIGCHLD);

log.c

@@ -24,22 +24,53 @@ static void log_stack_trace(void)
 }
 
 int log_level = W_LOG_ERR;
+static pthread_key_t thread_name_key;
+
+static __attribute__((constructor))
+void register_thread_name(void) {
+  pthread_key_create(&thread_name_key, free);
+}
+
+const char *w_get_thread_name(void) {
+  const char *name = pthread_getspecific(thread_name_key);
+  if (name) {
+    return name;
+  }
+  return w_set_thread_name("%" PRIu32, (uint32_t)(uintptr_t)pthread_self());
+}
+
+const char *w_set_thread_name(const char *fmt, ...) {
+  char *name = NULL;
+  va_list ap;
+  free(pthread_getspecific(thread_name_key));
+  va_start(ap, fmt);
+  vasprintf(&name, fmt, ap);
+  va_end(ap);
+  pthread_setspecific(thread_name_key, name);
+  return name;
+}
 
 void w_log(int level, const char *fmt, ...)
 {
   char buf[4096];
   va_list ap;
   int len;
-  uint32_t tid = (uint32_t)(uintptr_t)pthread_self();
   bool fatal = false;
+  struct timeval tv;
+  char timebuf[64];
+  struct tm tm;
 
   if (level == W_LOG_FATAL) {
     level = W_LOG_ERR;
     fatal = true;
   }
 
-  len = snprintf(buf, sizeof(buf),
-        "%d: tid=%" PRIu32 " ", (int)time(NULL), tid);
+  gettimeofday(&tv, NULL);
+  localtime_r(&tv.tv_sec, &tm);
+  strftime(timebuf, sizeof(timebuf), "%Y-%m-%dT%H:%M:%S", &tm);
+
+  len = snprintf(buf, sizeof(buf), "%s,%03d: [%s] ",
+         timebuf, (int)tv.tv_usec / 1000, w_get_thread_name());
   va_start(ap, fmt);
   vsnprintf(buf + len, sizeof(buf) - len, fmt, ap);
   va_end(ap);

main.c

@@ -56,6 +56,7 @@ static void run_service(void)
   /* we are the child, let's set things up */
   ignore_result(chdir("/"));
 
+  w_set_thread_name("listener");
   watchman_watcher_init();
   res = w_start_listener(sock_name);
   watchman_watcher_dtor();
@@ -228,6 +229,7 @@ static void spawn_via_launchd(void)
 "        <string>%s</string>\n"
 "        <string>--foreground</string>\n"
 "        <string>--logfile=%s</string>\n"
+"        <string>--log-level=%d</string>\n"
 "        <string>--sockname=%s</string>\n"
 "        <string>--statefile=%s</string>\n"
 "    </array>\n"
@@ -253,7 +255,8 @@ static void spawn_via_launchd(void)
 "    </dict>\n"
 "</dict>\n"
 "</plist>\n",
-    watchman_path, log_name, sock_name, watchman_state_file, sock_name,
+    watchman_path, log_name, log_level, sock_name,
+    watchman_state_file, sock_name,
     getenv("PATH"));
   fclose(fp);
   // Don't rely on umask, ensure we have the correct perms
@@ -598,6 +601,7 @@ int main(int argc, char **argv)
     return 0;
   }
 
+  w_set_thread_name("cli");
   cmd = build_command(argc, argv);
   preprocess_command(cmd, output_pdu);
 

root.c

@@ -1278,17 +1278,17 @@ static void process_subscriptions(w_root_t *root)
     struct watchman_client *client = w_ht_val_ptr(iter.value);
     w_ht_iter_t citer;
 
-    w_log(W_LOG_DBG, "client=%p fd=%d\n", client, client->fd);
-
     if (w_ht_first(client->subscriptions, &citer)) do {
       struct watchman_client_subscription *sub = w_ht_val_ptr(citer.value);
 
       if (sub->root != root) {
         w_log(W_LOG_DBG, "root doesn't match, skipping\n");
         continue;
       }
-      w_log(W_LOG_DBG, "sub=%p %s, last=%" PRIu32 " pending=%" PRIu32 "\n",
-          sub, sub->name->buf, sub->last_sub_tick, root->pending_sub_tick);
+      w_log(W_LOG_DBG, "client->fd=%d sub=%p %s, last=%" PRIu32
+          " pending=%" PRIu32 "\n",
+          client->fd, sub, sub->name->buf, sub->last_sub_tick,
+          root->pending_sub_tick);
 
       if (sub->last_sub_tick == root->pending_sub_tick) {
         continue;
@@ -1572,8 +1572,7 @@ static void notify_thread(w_root_t *root)
       root->done_initial = true;
       w_root_unlock(root);
 
-      w_log(W_LOG_DBG, "notify_thread[%s]: initial crawl complete\n",
-            root->root_path->buf);
+      w_log(W_LOG_DBG, "initial crawl complete\n");
     }
 
     if (!wait_for_notify(root, timeoutms)) {
@@ -1583,8 +1582,6 @@ static void notify_thread(w_root_t *root)
         goto unlock;
       }
 
-      w_log(W_LOG_DBG, "notify_thread[%s] assessing triggers\n",
-          root->root_path->buf);
       process_subscriptions(root);
       process_triggers(root);
       consider_age_out(root);
@@ -2015,10 +2012,10 @@ static void *run_notify_thread(void *arg)
 {
   w_root_t *root = arg;
 
+  w_set_thread_name("notify %.*s", root->root_path->len, root->root_path->buf);
   notify_thread(root);
 
-  w_log(W_LOG_DBG, "notify_thread: out of loop %s\n",
-      root->root_path->buf);
+  w_log(W_LOG_DBG, "out of loop\n");
 
   /* we'll remove it from watched roots if it isn't
    * already out of there */

watcher/fsevents.c

@@ -151,9 +151,9 @@ static void fse_pipe_callback(CFFileDescriptorRef fdref,
 
   unused_parameter(fdref);
   unused_parameter(callBackTypes);
+  unused_parameter(root);
 
-  w_log(W_LOG_DBG, "fse_thread[%.*s]: pipe signalled\n",
-      root->root_path->len, root->root_path->buf);
+  w_log(W_LOG_DBG, "pipe signalled\n");
   CFRunLoopStop(CFRunLoopGetCurrent());
 }
 
@@ -169,6 +169,9 @@ static void *fsevents_thread(void *arg)
   struct fsevents_root_state *state = root->watch;
   double latency;
 
+  w_set_thread_name("fsevents %.*s", root->root_path->len,
+      root->root_path->buf);
+
   // Block until fsevents_root_start is waiting for our initialization
   pthread_mutex_lock(&state->fse_mtx);
 
@@ -269,8 +272,7 @@ static void *fsevents_thread(void *arg)
   pthread_cond_signal(&state->fse_cond);
   pthread_mutex_unlock(&state->fse_mtx);
 
-  w_log(W_LOG_DBG, "fse_thread[%.*s] done\n",
-      root->root_path->len, root->root_path->buf);
+  w_log(W_LOG_DBG, "fse_thread done\n");
   w_root_delref(root);
   return NULL;
 }

watchman.h

@@ -477,6 +477,8 @@ bool w_reap_children(bool block);
 
 extern int log_level;
 extern char *log_name;
+const char *w_set_thread_name(const char *fmt, ...);
+const char *w_get_thread_name(void);
 void w_log(int level, const char *fmt, ...)
 #ifdef __GNUC__
   __attribute__((format(printf, 2, 3)))