Clean up CLI logging, moving protocol work to --verbose. (#556)

lighthouse-cli/index.js

@@ -27,7 +27,6 @@ if (!environment.checkNodeCompatibility()) {
 const yargs = require('yargs');
 const Printer = require('./printer');
 const lighthouse = require('../lighthouse-core');
-const log = require('../lighthouse-core/lib/log');
 
 const cli = yargs
   .help('help')
@@ -127,7 +126,7 @@ if (cli.listTraceCategories) {
 
 const url = cli._[0];
 const outputMode = cli.output;
-const outputPath = cli.outputPath;
+const outputPath = cli['output-path'];
 const flags = cli;
 const config = (cli.configPath && require(cli.configPath)) || null;
 
@@ -146,25 +145,6 @@ if (!flags.auditWhitelist || flags.auditWhitelist === 'all') {
   flags.auditWhitelist = new Set(flags.auditWhitelist.split(',').map(a => a.toLowerCase()));
 }
 
-// Listen on progress events, record their start timestamps
-// and print result using the logger.
-let timers = {};
-log.events.on('status', function(event) {
-  let msg = event[1];
-  if (!msg) {
-    return;
-  }
-  timers[msg] = Date.now();
-});
-log.events.on('statusEnd', function(event) {
-  let msg = event[1];
-  if (!msg) {
-    return;
-  }
-  let t = Date.now() - timers[msg];
-  log.log('Timer', `${msg} ${t}ms`);
-});
-
 // kick off a lighthouse run
 lighthouse(url, flags, config)
   .then(results => Printer.write(results, outputMode, outputPath))

lighthouse-cli/printer.js

@@ -130,7 +130,13 @@ function createOutput(results, outputMode) {
  * @return {!Promise}
  */
 function writeToStdout(output) {
-  return Promise.resolve(process.stdout.write(`${output}\n`));
+  return new Promise((resolve, reject) => {
+    // small delay to avoid race with debug() logs
+    setTimeout(_ => {
+      process.stdout.write(`${output}\n`);
+      resolve();
+    }, 50);
+  });
 }
 
 /**

lighthouse-core/gather/drivers/cri.js

@@ -105,14 +105,14 @@ class CriDriver extends Driver {
     }
 
     return new Promise((resolve, reject) => {
-      this.formattedLog('method => browser', {method: command, params: params});
+      this.formattedLog('method => browser', {method: command, params: params}, 'verbose');
 
       this._cri.send(command, params, (err, result) => {
         if (err) {
           this.formattedLog('method <= browser ERR', {method: command, params: result}, 'error');
           return reject(result);
         }
-        this.formattedLog('method <= browser OK', {method: command, params: result});
+        this.formattedLog('method <= browser OK', {method: command, params: result}, 'verbose');
         resolve(result);
       });
     });

lighthouse-core/gather/drivers/driver.js

@@ -75,7 +75,9 @@ class Driver {
   formattedLog(prefix, data, level) {
     const columns = (!process || process.browser) ? Infinity : process.stdout.columns;
     const maxLength = columns - data.method.length - prefix.length - 18;
-    const snippet = data.params ? JSON.stringify(data.params).substr(0, maxLength) : '';
+    // IO.read blacklisted here to avoid logging megabytes of trace data
+    const snippet = (data.params && data.method !== 'IO.read') ?
+        JSON.stringify(data.params).substr(0, maxLength) : '';
     log[level ? level : 'log'](prefix, data.method, snippet);
   }
 
@@ -101,7 +103,7 @@ class Driver {
     }
 
     // log event listeners being bound
-    this.formattedLog('listen for event =>', {method: eventName});
+    this.formattedLog('listen for event =>', {method: eventName}, 'verbose');
     this._eventEmitter.on(eventName, cb);
   }
 
@@ -116,7 +118,7 @@ class Driver {
       throw new Error('connect() must be called before attempting to listen to events.');
     }
     // log event listeners being bound
-    this.formattedLog('listen once for event =>', {method: eventName});
+    this.formattedLog('listen once for event =>', {method: eventName}, 'verbose');
     this._eventEmitter.once(eventName, cb);
   }
 

lighthouse-core/gather/drivers/extension.js

@@ -109,7 +109,7 @@ class ExtensionDriver extends Driver {
    */
   sendCommand(command, params) {
     return new Promise((resolve, reject) => {
-      this.formattedLog('method => browser', {method: command, params: params});
+      this.formattedLog('method => browser', {method: command, params: params}, 'verbose');
       if (!this._tabId) {
         log.error('No tabId set for sendCommand');
       }
@@ -124,7 +124,7 @@ class ExtensionDriver extends Driver {
           return reject(result.exceptionDetails);
         }
 
-        this.formattedLog('method <= browser OK', {method: command, params: result});
+        this.formattedLog('method <= browser OK', {method: command, params: result}, 'verbose');
         resolve(result);
       });
     });

lighthouse-core/gather/gather-runner.js

@@ -119,7 +119,7 @@ class GatherRunner {
         log.log('status', `Gathering: trace "${traceName}"`);
         return driver.endTrace().then(traceContents => {
           loadData.traces[traceName] = {traceContents};
-          log.log('statusEnd', `Gathering: trace "${traceName}"`);
+          log.verbose('statusEnd', `Gathering: trace "${traceName}"`);
         });
       });
     }
@@ -130,7 +130,7 @@ class GatherRunner {
         log.log('status', status);
         return driver.endNetworkCollect().then(networkRecords => {
           loadData.networkRecords = networkRecords;
-          log.log('statusEnd', status);
+          log.verbose('statusEnd', status);
         });
       });
     }
@@ -144,7 +144,7 @@ class GatherRunner {
               loadData.traceContents = loadData.traces[traceName].traceContents;
             }
             return Promise.resolve(gatherer.afterPass(options, loadData)).then(ret => {
-              log.log('statusEnd', status);
+              log.verbose('statusEnd', status);
               return ret;
             });
           });

lighthouse-core/lib/log.js

@@ -38,16 +38,21 @@ function _log(title, logargs) {
   return loggers[title](...args);
 }
 
-class Emitter extends EventEmitter { }
-const events = new Emitter();
+class Emitter extends EventEmitter {
+  // issueStatus fires off all status updates
+  // listen with `require('lib/log').events.addListener('status', callback)`
+  issueStatus(title, args) {
+    if (title === 'status' || title === 'statusEnd') {
+      this.emit(title, args);
+    }
+  }
+}
 
 module.exports = {
   setLevel,
-  events,
+  events: new Emitter(),
   log(title) {
-    if (title === 'status' || title === 'statusEnd') {
-      events.emit(title, arguments);
-    }
+    this.events.issueStatus(title, arguments);
     return _log(title, arguments);
   },
 
@@ -60,6 +65,7 @@ module.exports = {
   },
 
   verbose(title) {
+    this.events.issueStatus(title, arguments);
     return _log(`${title}:verbose`, arguments);
   }
 };

lighthouse-core/runner.js

@@ -68,7 +68,7 @@ class Runner {
         const status = `Evaluating: ${audit.meta.description}`;
         log.log('status', status);
         return Promise.resolve(audit.audit(artifacts)).then(ret => {
-          log.log('statusEnd', status);
+          log.verbose('statusEnd', status);
           return ret;
         });
       })));