Revamp debug logging

Summary:
- Switch namespace prefix from `ReactNativePackager:` to `RNP:`
- Add logging for handled requests
- Log transform cache key
- Add logging for transform cache hits/misses

Reviewed By: jeanlauliac

Differential Revision: D4377867

fbshipit-source-id: 9ec2060432f8c5e68561d3fe8ec7127f76c4a081

local-cli/server/util/inspectorProxy.js

@@ -45,7 +45,7 @@ const querystring = require('querystring');
 const parseUrl = require('url').parse;
 const WebSocket = require('ws');
 
-const debug = require('debug')('ReactNativePackager:InspectorProxy');
+const debug = require('debug')('RNP:InspectorProxy');
 const launchChrome = require('./launchChrome');
 
 type DevicePage = {
@@ -456,7 +456,7 @@ function attachToServer(server: http.Server, pathPrefix: string): InspectorProxy
 
 if (!module.parent) {
   console.info('Starting server');
-  process.env.DEBUG = 'ReactNativePackager:Inspector';
+  process.env.DEBUG = 'RNP:Inspector';
   const serverInstance = http.createServer().listen(
     8081,
     'localhost',

packager/README.md

@@ -133,9 +133,9 @@ Builds a bundle according to the provided options.
 
 To get verbose output when running the packager, define an environment variable:
 
-    export DEBUG=ReactNativePackager:*
+    export DEBUG=RNP:*
 
-You can combine this with other values, e.g. `DEBUG=babel,ReactNativePackager:*`. Under the hood this uses the [`debug`](https://www.npmjs.com/package/debug) package, see its documentation for all the available options.
+You can combine this with other values, e.g. `DEBUG=babel,RNP:*`. Under the hood this uses the [`debug`](https://www.npmjs.com/package/debug) package, see its documentation for all the available options.
 
 The `/debug` endpoint discussed above is also useful.
 

packager/react-packager/index.js

@@ -40,7 +40,7 @@ function enableDebug() {
   // To enable debugging, we need to set our pattern or append it to any
   // existing pre-configured pattern to avoid disabling logging for
   // other packages
-  var debugPattern = 'ReactNativePackager:*';
+  var debugPattern = 'RNP:*';
   var existingPattern = debug.load();
   if (existingPattern) {
     debugPattern += ',' + existingPattern;

packager/react-packager/src/Bundler/index.js

@@ -13,6 +13,7 @@
 
 const assert = require('assert');
 const crypto = require('crypto');
+const debug = require('debug')('RNP:Bundler');
 const fs = require('fs');
 const Cache = require('../node-haste').Cache;
 const Transformer = require('../JSTransformer');
@@ -194,6 +195,8 @@ class Bundler {
       cacheKeyParts.join('$'),
     ).digest('hex');
 
+    debug(`Using transform cache key "${transformCacheKey}"`);
+
     this._cache = new Cache({
       resetCache: opts.resetCache,
       cacheKey: transformCacheKey,

packager/react-packager/src/JSTransformer/index.js

@@ -18,7 +18,7 @@ const denodeify = require('denodeify');
 const os = require('os');
 const util = require('util');
 const workerFarm = require('worker-farm');
-const debug = require('debug')('ReactNativePackager:JStransformer');
+const debug = require('debug')('RNP:JStransformer');
 
 import type {Data as TransformData, Options as TransformOptions} from './worker/worker';
 import type {SourceMap} from '../lib/SourceMap';

packager/react-packager/src/Server/__tests__/Server-test.js

@@ -322,7 +322,7 @@ describe('processRequest', () => {
 
     beforeEach(() => {
       EventEmitter = require.requireActual('events').EventEmitter;
-      req = new EventEmitter();
+      req = scaffoldReq(new EventEmitter());
       req.url = '/onchange';
       res = {
         writeHead: jest.fn(),
@@ -349,7 +349,7 @@ describe('processRequest', () => {
 
   describe('/assets endpoint', () => {
     it('should serve simple case', () => {
-      const req = {url: '/assets/imgs/a.png'};
+      const req = scaffoldReq({url: '/assets/imgs/a.png'});
       const res = {end: jest.fn(), setHeader: jest.fn()};
 
       AssetServer.prototype.get.mockImplementation(() => Promise.resolve('i am image'));
@@ -360,7 +360,7 @@ describe('processRequest', () => {
     });
 
     it('should parse the platform option', () => {
-      const req = {url: '/assets/imgs/a.png?platform=ios'};
+      const req = scaffoldReq({url: '/assets/imgs/a.png?platform=ios'});
       const res = {end: jest.fn(), setHeader: jest.fn()};
 
       AssetServer.prototype.get.mockImplementation(() => Promise.resolve('i am image'));
@@ -372,7 +372,10 @@ describe('processRequest', () => {
     });
 
     it('should serve range request', () => {
-      const req = {url: '/assets/imgs/a.png?platform=ios', headers: {range: 'bytes=0-3'}};
+      const req = scaffoldReq({
+        url: '/assets/imgs/a.png?platform=ios',
+        headers: {range: 'bytes=0-3'},
+      });
       const res = {end: jest.fn(), writeHead: jest.fn(), setHeader: jest.fn()};
       const mockData = 'i am image';
 
@@ -385,7 +388,7 @@ describe('processRequest', () => {
     });
 
     it('should serve assets files\'s name contain non-latin letter', () => {
-      const req = {url: '/assets/imgs/%E4%B8%BB%E9%A1%B5/logo.png'};
+      const req = scaffoldReq({url: '/assets/imgs/%E4%B8%BB%E9%A1%B5/logo.png'});
       const res = {end: jest.fn(), setHeader: jest.fn()};
 
       AssetServer.prototype.get.mockImplementation(() => Promise.resolve('i am image'));
@@ -522,4 +525,12 @@ describe('processRequest', () => {
       });
     });
   });
+
+  // ensures that vital properties exist on fake request objects
+  function scaffoldReq(req) {
+    if (!req.headers) {
+      req.headers = {};
+    }
+    return req;
+  }
 });

packager/react-packager/src/Server/index.js

@@ -24,7 +24,7 @@ const path = require('path');
 const terminal = require('../lib/terminal');
 const url = require('url');
 
-const debug = require('debug')('ReactNativePackager:Server');
+const debug = require('debug')('RNP:Server');
 
 import type Module from '../node-haste/Module';
 import type {Stats} from 'fs';
@@ -671,6 +671,8 @@ class Server {
     next: () => mixed,
   ) {
     const urlObj = url.parse(req.url, true);
+    const {host} = req.headers;
+    debug(`Handling request: ${host ? 'http://' + host : ''}${req.url}`);
     /* $FlowFixMe: Could be empty if the URL is invalid. */
     const pathname: string = urlObj.pathname;
 

packager/react-packager/src/lib/TransformCache.js

@@ -11,6 +11,7 @@
 
 'use strict';
 
+const debugRead = require('debug')('RNP:TransformCache:Read');
 const fs = require('fs');
 /**
  * We get the package "for free" with "write-file-atomic". MurmurHash3 is a
@@ -46,6 +47,10 @@ const getCacheDirPath = (function () {
         require('os').tmpdir(),
         CACHE_NAME + '-' + imurmurhash(__dirname).result().toString(16),
       );
+
+      require('debug')('RNP:TransformCache:Dir')(
+        `transform cache directory: ${dirPath}`
+      );
     }
     return dirPath;
   };
@@ -329,5 +334,10 @@ function readSync(props: ReadTransformProps): ?CachedResult {
 
 module.exports = {
   writeSync,
-  readSync,
+  readSync(props: ReadTransformProps): ?CachedResult {
+    const result = readSync(props);
+    const msg = result ? 'Cache hit: ' : 'Cache miss: ';
+    debugRead(msg + props.filePath);
+    return result;
+  }
 };

packager/react-packager/src/node-haste/DependencyGraph/ResolutionRequest.js

@@ -13,7 +13,7 @@
 const AsyncTaskGroup = require('../lib/AsyncTaskGroup');
 const MapWithDefaults = require('../lib/MapWithDefaults');
 
-const debug = require('debug')('ReactNativePackager:DependencyGraph');
+const debug = require('debug')('RNP:DependencyGraph');
 const util = require('util');
 const path = require('path');
 const realPath = require('path');