feat(run): Log package name and timing in runScriptInPackageCapturing (…

…#1781)

commands/run/index.js

@@ -7,6 +7,7 @@ const npmRunScript = require("@lerna/npm-run-script");
 const batchPackages = require("@lerna/batch-packages");
 const runParallelBatches = require("@lerna/run-parallel-batches");
 const output = require("@lerna/output");
+const timer = require("@lerna/timer");
 const ValidationError = require("@lerna/validation-error");
 const { getFilteredPackages } = require("@lerna/filter-options");
 
@@ -74,6 +75,7 @@ class RunCommand extends Command {
     );
 
     let chain = Promise.resolve();
+    const getElapsed = timer();
 
     if (this.options.parallel) {
       chain = chain.then(() => this.runScriptInPackagesParallel());
@@ -107,10 +109,11 @@ class RunCommand extends Command {
     return chain.then(() => {
       this.logger.success(
         "run",
-        "Ran npm script '%s' in %d %s:",
+        "Ran npm script '%s' in %d %s in %ss:",
         this.script,
         this.count,
-        this.packagePlural
+        this.packagePlural,
+        (getElapsed() / 1000).toFixed(1)
       );
       this.logger.success("", this.packagesWithScript.map(pkg => `- ${pkg.name}`).join("\n"));
     });
@@ -146,7 +149,15 @@ class RunCommand extends Command {
   }
 
   runScriptInPackageCapturing(pkg) {
+    const getElapsed = timer();
     return npmRunScript(this.script, this.getOpts(pkg)).then(result => {
+      this.logger.info(
+        "run",
+        "Ran npm script '%s' in '%s' in %ss:",
+        this.script,
+        pkg.name,
+        (getElapsed() / 1000).toFixed(1)
+      );
       output(result.stdout);
 
       return result;

commands/run/package.json

@@ -40,6 +40,7 @@
     "@lerna/npm-run-script": "file:../../utils/npm-run-script",
     "@lerna/output": "file:../../utils/output",
     "@lerna/run-parallel-batches": "file:../../utils/run-parallel-batches",
+    "@lerna/timer": "file:../../utils/timer",
     "@lerna/validation-error": "file:../../core/validation-error",
     "p-map": "^1.2.0"
   }

integration/lerna-run.test.js

@@ -3,6 +3,11 @@
 const cliRunner = require("@lerna-test/cli-runner");
 const initFixture = require("@lerna-test/init-fixture")(__dirname);
 
+const env = {
+  // Hush timing information
+  LERNA_INTEGRATION: "SKIP",
+};
+
 /**
  * NOTE: We do not test the "missing test script" case here
  * because Windows makes the snapshots impossible to stabilize.
@@ -13,7 +18,7 @@ describe("lerna run", () => {
     const args = ["run", "fail", "--", "--silent"];
 
     try {
-      await cliRunner(cwd)(...args);
+      await cliRunner(cwd, env)(...args);
     } catch (err) {
       expect(err.message).toMatch("npm run fail --silent exited 1 in 'package-3'");
       expect(err.code).toBe(1);
@@ -25,13 +30,15 @@ describe("lerna run", () => {
     const args = ["run", "fail", "--no-bail", "--concurrency", "1", "--", "--silent"];
 
     try {
-      await cliRunner(cwd)(...args);
+      await cliRunner(cwd, env)(...args);
     } catch (err) {
       expect(err.stderr).toMatchInlineSnapshot(`
 lerna notice cli __TEST_VERSION__
 lerna info Executing command in 2 packages: "npm run fail --silent"
+lerna info run Ran npm script 'fail' in 'package-3' in 0.0s:
+lerna info run Ran npm script 'fail' in 'package-1' in 0.0s:
 lerna ERR! Received non-zero exit code 100 during execution
-lerna success run Ran npm script 'fail' in 2 packages:
+lerna success run Ran npm script 'fail' in 2 packages in 0.0s:
 lerna success - package-1
 lerna success - package-3
 
@@ -54,7 +61,7 @@ lerna success - package-3
       "--",
       "--silent",
     ];
-    const { stdout, stderr } = await cliRunner(cwd)(...args);
+    const { stdout, stderr } = await cliRunner(cwd, env)(...args);
     expect(stdout).toMatchInlineSnapshot(`
 package-3: package-3
 package-4: package-4
@@ -64,7 +71,7 @@ package-2: package-2
     expect(stderr).toMatchInlineSnapshot(`
 lerna notice cli __TEST_VERSION__
 lerna info Executing command in 4 packages: "npm run test --silent"
-lerna success run Ran npm script 'test' in 4 packages:
+lerna success run Ran npm script 'test' in 4 packages in 0.0s:
 lerna success - package-1
 lerna success - package-2
 lerna success - package-3
@@ -84,7 +91,7 @@ lerna success - package-4
       "--",
       "--silent",
     ];
-    const { stdout, stderr } = await cliRunner(cwd)(...args);
+    const { stdout, stderr } = await cliRunner(cwd, env)(...args);
     expect(stdout).toMatchInlineSnapshot(`
 package-3
 package-4
@@ -94,7 +101,7 @@ package-2
     expect(stderr).toMatchInlineSnapshot(`
 lerna notice cli __TEST_VERSION__
 lerna info Executing command in 4 packages: "npm run test --silent"
-lerna success run Ran npm script 'test' in 4 packages:
+lerna success run Ran npm script 'test' in 4 packages in 0.0s:
 lerna success - package-1
 lerna success - package-2
 lerna success - package-3
@@ -112,11 +119,11 @@ lerna success - package-4
       "--",
       "--silent",
     ];
-    const { stdout, stderr } = await cliRunner(cwd)(...args);
+    const { stdout, stderr } = await cliRunner(cwd, env)(...args);
     expect(stderr).toMatchInlineSnapshot(`
 lerna notice cli __TEST_VERSION__
 lerna info Executing command in 4 packages: "npm run test --silent"
-lerna success run Ran npm script 'test' in 4 packages:
+lerna success run Ran npm script 'test' in 4 packages in 0.0s:
 lerna success - package-1
 lerna success - package-2
 lerna success - package-3

utils/timer/README.md

@@ -0,0 +1,9 @@
+# `@lerna/timer`
+
+> An internal Lerna tool
+
+## Usage
+
+You probably shouldn't, at least directly.
+
+Install [lerna](https://www.npmjs.com/package/lerna) for access to the `lerna` CLI.

utils/timer/package.json

@@ -0,0 +1,32 @@
+{
+  "name": "@lerna/timer",
+  "version": "3.0.0",
+  "description": "An internal Lerna tool",
+  "keywords": [
+    "lerna",
+    "utils"
+  ],
+  "homepage": "https://github.com/lerna/lerna",
+  "license": "MIT",
+  "author": {
+    "name": "Kevin Verdieck",
+    "url": "https://github.com/nomcopter"
+  },
+  "files": [
+    "timer.js"
+  ],
+  "main": "timer.js",
+  "engines": {
+    "node": ">= 6.9.0"
+  },
+  "publishConfig": {
+    "access": "public"
+  },
+  "repository": {
+    "type": "git",
+    "url": "git+https://github.com/lerna/lerna.git"
+  },
+  "scripts": {
+    "test": "echo \"Run tests from root\" && exit 1"
+  }
+}

utils/timer/timer.js

@@ -0,0 +1,13 @@
+"use strict";
+
+module.exports = timer;
+
+function timer() {
+  /* istanbul ignore if */
+  if (process.env.LERNA_INTEGRATION) {
+    return () => 0;
+  }
+
+  const startMillis = Date.now();
+  return () => Date.now() - startMillis;
+}