Add watch-related debug and perfLogger output to metro-file-map

Summary:
Adds some verbose logging output to show:
 - The chosen watcher (`watchman`/`fsevents`/`node`) - also annotated
 - Watchman command responses within `WatchmanWatcher`
 - Subscription event summaries and file change summaries

Debug logs use the `debug` NPM package, Metro logs can be enabled by setting `DEBUG=Metro:*` in the environment.

Reviewed By: motiz88

Differential Revision: D40022742

fbshipit-source-id: f0c3b69c0753f2a3f6470b6e79364e0b5732e954

flow-typed/fb-watchman.js

@@ -17,6 +17,7 @@ declare module 'fb-watchman' {
  }>;
 
  declare type WatchmanSubscribeResponse = $ReadOnly<{
+ subscribe: string,
  warning?: string,
  ...
  }>;

packages/metro-file-map/src/index.js

@@ -62,6 +62,7 @@ import AbortController from 'abort-controller';
 
 const nodeCrawl = require('./crawlers/node');
 const watchmanCrawl = require('./crawlers/watchman');
+const debug = require('debug')('Metro:FileMap');
 
 export type {
  BuildParameters,
@@ -869,6 +870,15 @@ export default class HasteMap extends EventEmitter {
  ? FSEventsWatcher
  : NodeWatcher;
 
+ let watcher = 'node';
+ if (WatcherImpl === WatchmanWatcher) {
+ watcher = 'watchman';
+ } else if (WatcherImpl === FSEventsWatcher) {
+ watcher = 'fsevents';
+ }
+ debug(`Using watcher: ${watcher}`);
+ this._options.perfLogger?.annotate({string: {watcher}});
+
  const extensions = this._options.extensions;
  const ignorePattern = this._options.ignorePattern;
  const rootDir = this._options.rootDir;

packages/metro-file-map/src/watchers/WatchmanWatcher.js

@@ -79,7 +79,7 @@ export default class WatchmanWatcher extends EventEmitter {
  );
  this.client.on('end', () => {
  console.warn(
- '[sane] Warning: Lost connection to watchman, reconnecting..',
+ '[metro-file-map] Warning: Lost connection to Watchman, reconnecting..',
  );
  self._init();
  });
@@ -94,6 +94,7 @@ export default class WatchmanWatcher extends EventEmitter {
  if (handleError(self, error)) {
  return;
  }
+ debug('Received watch-project response: %s', resp.relative_path);
 
  handleWarning(resp);
 
@@ -110,6 +111,7 @@ export default class WatchmanWatcher extends EventEmitter {
  return;
  }
 
+ debug('Received clock response: %s', resp.clock);
  const watchProjectInfo = self.watchProjectInfo;
 
  invariant(
@@ -148,6 +150,7 @@ export default class WatchmanWatcher extends EventEmitter {
  if (handleError(self, error)) {
  return;
  }
+ debug('Received subscribe response: %s', resp.subscribe);
 
  handleWarning(resp);
 
@@ -161,6 +164,14 @@ export default class WatchmanWatcher extends EventEmitter {
  * Handles a change event coming from the subscription.
  */
  _handleChangeEvent(resp: WatchmanSubscriptionEvent) {
+ debug(
+ 'Received subscription response: %s (fresh: %s}, files: %s, enter: %s, leave: %s)',
+ resp.subscription,
+ resp.is_fresh_instance,
+ resp.files?.length,
+ resp['state-enter'],
+ resp['state-leave'],
+ );
  assert.equal(resp.subscription, SUB_NAME, 'Invalid subscription event.');
  if (resp.is_fresh_instance) {
  this.emit('fresh_instance');
@@ -176,17 +187,17 @@ export default class WatchmanWatcher extends EventEmitter {
  (this.watchmanDeferStates ?? []).includes(resp['state-enter'])
  ) {
  debug(
- // $FlowFixMe[incompatible-type]
- `Watchman reports ${resp['state-enter']} just started. Filesystem notifications are paused.`,
+ 'Watchman reports "%s" just started. Filesystem notifications are paused.',
+ resp['state-enter'],
  );
  }
  if (
  resp['state-leave'] != null &&
  (this.watchmanDeferStates ?? []).includes(resp['state-leave'])
  ) {
  debug(
- // $FlowFixMe[incompatible-type]
- `Watchman reports ${resp['state-leave']} ended. Filesystem notifications resumed.`,
+ 'Watchman reports "%s" ended. Filesystem notifications resumed.',
+ resp['state-leave'],
  );
  }
  }
@@ -203,7 +214,19 @@ export default class WatchmanWatcher extends EventEmitter {
  'watch-project response should have been set before receiving subscription events',
  );
 
- const relativePath = changeDescriptor.name;
+ const {
+ name: relativePath,
+ new: isNew = false,
+ exists = false,
+ } = changeDescriptor;
+
+ debug(
+ 'Handling change to: %s (new: %s, exists: %s)',
+ relativePath,
+ isNew,
+ exists,
+ );
+
  const absPath = path.join(
  watchProjectInfo.root,
  watchProjectInfo.relativePath,
@@ -217,7 +240,7 @@ export default class WatchmanWatcher extends EventEmitter {
  return;
  }
 
- if (!changeDescriptor.exists) {
+ if (!exists) {
  self._emitEvent(DELETE_EVENT, relativePath, self.root);
  } else {
  fs.lstat(absPath, (error, stat) => {
@@ -231,7 +254,7 @@ export default class WatchmanWatcher extends EventEmitter {
  return;
  }
 
- const eventType = changeDescriptor.new ? ADD_EVENT : CHANGE_EVENT;
+ const eventType = isNew ? ADD_EVENT : CHANGE_EVENT;
 
  // Change event on dirs are mostly useless.
  if (!(eventType === CHANGE_EVENT && stat.isDirectory())) {