From ded5171a49afcf795c1398131fe567b3003a2e82 Mon Sep 17 00:00:00 2001 From: Zoltan Kochan Date: Sun, 23 Dec 2018 16:42:27 +0200 Subject: [PATCH] feat: better reporting of child processes output PR #1573 * feat(reporting): collapse build output of deps inside node_modules ref #1440 * feat(reporting): nicer reporting of lifecycle output * feat(reporting): print the number of collapsed lines * feat(reporting): always print the status of the child processes * refactor: reporting * feat(reporting): nicer indentation * feat(reporting): report duration of script run close #1440 --- packages/core-loggers/src/lifecycleLogger.ts | 2 + packages/default-reporter/package.json | 2 +- .../reportLifecycleScripts.ts | 193 ++++-- .../reporterForClient/utils/formatPrefix.ts | 6 +- packages/default-reporter/test/index.ts | 174 +----- .../test/reportingLifecycleScripts.ts | 574 ++++++++++++++++++ packages/default-reporter/typings/local.d.ts | 6 +- packages/headless/src/index.ts | 2 + .../headless/src/runDependenciesScripts.ts | 1 + packages/lifecycle/src/index.ts | 13 +- packages/lifecycle/test/index.ts | 17 +- packages/supi/src/install/index.ts | 3 + packages/supi/src/rebuild/index.ts | 2 + shrinkwrap.yaml | 20 +- 14 files changed, 779 insertions(+), 236 deletions(-) create mode 100644 packages/default-reporter/test/reportingLifecycleScripts.ts diff --git a/packages/core-loggers/src/lifecycleLogger.ts b/packages/core-loggers/src/lifecycleLogger.ts index 41bf5ee89b..dfb30f72f0 100644 --- a/packages/core-loggers/src/lifecycleLogger.ts +++ b/packages/core-loggers/src/lifecycleLogger.ts @@ -14,8 +14,10 @@ export type LifecycleMessage = { stdio: 'stdout' | 'stderr', } | { exitCode: number, + optional: boolean, } | { script: string, + optional: boolean, }) export type LifecycleLog = {name: 'pnpm:lifecycle'} & LogBase & LifecycleMessage diff --git a/packages/default-reporter/package.json b/packages/default-reporter/package.json index fa66790580..74e4e07ab3 100644 --- a/packages/default-reporter/package.json +++ b/packages/default-reporter/package.json @@ -49,12 +49,12 @@ "most": "1.7.3", "normalize-path": "3.0.0", "pretty-bytes": "5.1.0", + "pretty-time": "1.1.0", "ramda": "0.26.1", "right-pad": "1.0.1", "semver": "5.6.0", "stacktracey": "1.2.106", "string-length": "2.0.0", - "string.prototype.padstart": "3.0.0", "strip-ansi": "5.0.0", "zen-push": "0.2.1" }, diff --git a/packages/default-reporter/src/reporterForClient/reportLifecycleScripts.ts b/packages/default-reporter/src/reporterForClient/reportLifecycleScripts.ts index 64f27e76b3..fa7e5a13b3 100644 --- a/packages/default-reporter/src/reporterForClient/reportLifecycleScripts.ts +++ b/packages/default-reporter/src/reporterForClient/reportLifecycleScripts.ts @@ -1,16 +1,17 @@ import { LifecycleLog } from '@pnpm/core-loggers' import chalk from 'chalk' import most = require('most') -import rightPad = require('right-pad') -import padStart = require('string.prototype.padstart') +import path = require('path') +import prettyTime = require('pretty-time') import stripAnsi = require('strip-ansi') import PushStream = require('zen-push') import { EOL } from '../constants' import { hlValue, - PREFIX_MAX_LENGTH, } from './outputConstants' -import formatPrefix from './utils/formatPrefix' +import formatPrefix, { formatPrefixNoTrim } from './utils/formatPrefix' + +const NODE_MODULES = `${path.sep}node_modules${path.sep}` export default ( log$: { @@ -22,19 +23,21 @@ export default ( width: number, }, ) => { -// When the reporter is not append-only, the length of output is limited + // When the reporter is not append-only, the length of output is limited // in order to reduce flickering - const formatLifecycle = formatLifecycleHideOverflow.bind(null, opts.appendOnly ? Infinity : opts.width) if (opts.appendOnly) { return most.of( log$.lifecycle - .map((log: LifecycleLog) => ({ msg: formatLifecycle(opts.cwd, log) })), + .map((log: LifecycleLog) => ({ msg: formatLifecycleHideOverflowForAppendOnly(opts.cwd, log) })), ) } const lifecycleMessages: { [depPath: string]: { + collapsed: boolean, output: string[], script: string, + startTime: [number, number], + status: string, }, } = {} const lifecycleStreamByDepPath: { @@ -50,25 +53,28 @@ export default ( log$.lifecycle // tslint:disable-line .forEach((log: LifecycleLog) => { const key = `${log.stage}:${log.depPath}` - lifecycleMessages[key] = lifecycleMessages[key] || { output: [] } - if (log['script']) { - lifecycleMessages[key].script = formatLifecycle(opts.cwd, log) + lifecycleMessages[key] = lifecycleMessages[key] || { + collapsed: log.wd.includes(NODE_MODULES), + output: [], + startTime: process.hrtime(), + status: formatIndentedStatus(chalk.magentaBright('Running...')), + } + const exit = typeof log['exitCode'] === 'number' + let msg: string + if (lifecycleMessages[key].collapsed) { + msg = renderCollapsedScriptOutput(log, lifecycleMessages[key], { cwd: opts.cwd, exit, maxWidth: opts.width }) } else { - if (!lifecycleMessages[key].output.length || log['exitCode'] !== 0) { - lifecycleMessages[key].output.push(formatLifecycle(opts.cwd, log)) - } - if (lifecycleMessages[key].output.length > 3) { - lifecycleMessages[key].output.shift() - } + msg = renderScriptOutput(log, lifecycleMessages[key], { cwd: opts.cwd, exit, maxWidth: opts.width }) + } + if (exit) { + delete lifecycleMessages[key] } if (!lifecycleStreamByDepPath[key]) { lifecycleStreamByDepPath[key] = new PushStream() lifecyclePushStream.next(most.from(lifecycleStreamByDepPath[key].observable)) } - lifecycleStreamByDepPath[key].next({ - msg: EOL + [lifecycleMessages[key].script].concat(lifecycleMessages[key].output).join(EOL), - }) - if (typeof log['exitCode'] === 'number') { + lifecycleStreamByDepPath[key].next({ msg }) + if (exit) { lifecycleStreamByDepPath[key].complete() } }) @@ -76,33 +82,146 @@ export default ( return most.from(lifecyclePushStream.observable) as most.Stream> } +function renderCollapsedScriptOutput ( + log: LifecycleLog, + messageCache: { + collapsed: boolean, + output: string[], + script: string, + startTime: [number, number], + status: string, + }, + opts: { + cwd: string, + exit: boolean, + maxWidth: number, + }, +) { + messageCache['label'] = messageCache['label'] || + `${highlightLastFolder(formatPrefixNoTrim(opts.cwd, log.wd))}: Running ${log.stage} script` + if (!opts.exit) { + updateMessageCache(log, messageCache, opts) + return `${messageCache['label']}...` + } + const time = prettyTime(process.hrtime(messageCache.startTime)) + if (log['exitCode'] === 0) { + return `${messageCache['label']}, done in ${time}` + } + if (log['optional'] === true) { + return `${messageCache['label']}, failed in ${time} (skipped as optional)` + } + return `${messageCache['label']}, failed in ${time}${EOL}${renderScriptOutput(log, messageCache, opts)}` +} + +function renderScriptOutput ( + log: LifecycleLog, + messageCache: { + collapsed: boolean, + output: string[], + script: string, + startTime: [number, number], + status: string, + }, + opts: { + cwd: string, + exit: boolean, + maxWidth: number, + }, +) { + updateMessageCache(log, messageCache, opts) + if (opts.exit && log['exitCode'] !== 0) { + return [ + messageCache.script, + ...messageCache.output, + messageCache.status, + ].join(EOL) + } + if (messageCache.output.length > 10) { + return [ + messageCache.script, + `[${messageCache.output.length - 10} lines collapsed]`, + ...messageCache.output.slice(messageCache.output.length - 10), + messageCache.status, + ].join(EOL) + } + return [ + messageCache.script, + ...messageCache.output, + messageCache.status, + ].join(EOL) +} + +function updateMessageCache ( + log: LifecycleLog, + messageCache: { + collapsed: boolean, + output: string[], + script: string, + startTime: [number, number], + status: string, + }, + opts: { + cwd: string, + exit: boolean, + maxWidth: number, + }, +) { + if (log['script']) { + const prefix = formatLifecycleScriptPrefix(opts.cwd, log.wd, log.stage) + const maxLineWidth = opts.maxWidth - prefix.length - 2 + ANSI_ESCAPES_LENGTH_OF_PREFIX + messageCache.script = `${prefix}$ ${cutLine(log['script'], maxLineWidth)}` + } else if (opts.exit) { + const time = prettyTime(process.hrtime(messageCache.startTime)) + if (log['exitCode'] === 0) { + messageCache.status = formatIndentedStatus(chalk.magentaBright(`Done in ${time}`)) + } else { + messageCache.status = formatIndentedStatus(chalk.red(`Failed in ${time}`)) + } + } else { + messageCache.output.push(formatIndentedOutput(opts.maxWidth, log)) + } +} + +function formatIndentedStatus (status: string) { + return `${chalk.magentaBright('└─')} ${status}` +} + +function highlightLastFolder (p: string) { + const lastSlash = p.lastIndexOf('/') + 1 + return `${chalk.gray(p.substr(0, lastSlash))}${p.substr(lastSlash)}` +} + const ANSI_ESCAPES_LENGTH_OF_PREFIX = hlValue(' ').length - 1 -function formatLifecycleHideOverflow ( - maxWidth: number, +function formatLifecycleHideOverflowForAppendOnly ( cwd: string, logObj: LifecycleLog, ) { - const prefix = `${ - logObj.wd === logObj.depPath - ? rightPad(formatPrefix(cwd, logObj.wd), PREFIX_MAX_LENGTH) - : rightPad(logObj.depPath, PREFIX_MAX_LENGTH) - } | ${hlValue(padStart(logObj.stage, 11))}` + const prefix = formatLifecycleScriptPrefix(cwd, logObj.wd, logObj.stage) + if (typeof logObj['exitCode'] === 'number') { + if (logObj['exitCode'] === 0) { + return `${prefix}: Done` + } else { + return `${prefix}: Failed` + } + } if (logObj['script']) { return `${prefix}$ ${logObj['script']}` } - if (logObj['exitCode'] === 0) { - return `${prefix}: done` - } - const maxLineWidth = maxWidth - prefix.length - 2 + ANSI_ESCAPES_LENGTH_OF_PREFIX - const line = formatLine(maxLineWidth, logObj) + const line = formatLine(Infinity, logObj) return `${prefix}: ${line}` } -function formatLine (maxWidth: number, logObj: LifecycleLog) { - if (typeof logObj['exitCode'] === 'number') return chalk.red(`Exited with ${logObj['exitCode']}`) +function formatIndentedOutput (maxWidth: number, logObj: LifecycleLog) { + return `${chalk.magentaBright('│')} ${formatLine(maxWidth - 2, logObj)}` +} - const line = stripAnsi(logObj['line']).substr(0, maxWidth) +function formatLifecycleScriptPrefix (cwd: string, wd: string, stage: string) { + return `${formatPrefix(cwd, wd)} ${hlValue(stage)}` +} + +function formatLine (maxWidth: number, logObj: LifecycleLog) { + const line = cutLine(logObj['line'], maxWidth) // TODO: strip only the non-color/style ansi escape codes if (logObj['stdio'] === 'stderr') { @@ -110,3 +229,7 @@ function formatLine (maxWidth: number, logObj: LifecycleLog) { } return line } + +function cutLine (line: string, maxLength: number) { + return stripAnsi(line).substr(0, maxLength) +} diff --git a/packages/default-reporter/src/reporterForClient/utils/formatPrefix.ts b/packages/default-reporter/src/reporterForClient/utils/formatPrefix.ts index 0c296b088b..293b149367 100644 --- a/packages/default-reporter/src/reporterForClient/utils/formatPrefix.ts +++ b/packages/default-reporter/src/reporterForClient/utils/formatPrefix.ts @@ -3,7 +3,7 @@ import path = require('path') import { PREFIX_MAX_LENGTH } from '../outputConstants' export default function formatPrefix (cwd: string, prefix: string) { - prefix = normalize(path.relative(cwd, prefix) || '.') + prefix = formatPrefixNoTrim(cwd, prefix) if (prefix.length <= PREFIX_MAX_LENGTH) { return prefix @@ -19,3 +19,7 @@ export default function formatPrefix (cwd: string, prefix: string) { return `...${shortPrefix.substr(separatorLocation)}` } + +export function formatPrefixNoTrim (cwd: string, prefix: string) { + return normalize(path.relative(cwd, prefix) || '.') +} diff --git a/packages/default-reporter/test/index.ts b/packages/default-reporter/test/index.ts index 635e20f74e..5b98eb4aa6 100644 --- a/packages/default-reporter/test/index.ts +++ b/packages/default-reporter/test/index.ts @@ -3,7 +3,6 @@ import { PnpmConfigs } from '@pnpm/config' import { deprecationLogger, hookLogger, - lifecycleLogger, packageJsonLogger, progressLogger, rootLogger, @@ -26,6 +25,7 @@ import path = require('path') import R = require('ramda') import StackTracey = require('stacktracey') import test = require('tape') +import './reportingLifecycleScripts' import './reportingScope' const WARN = chalk.bgYellow.black('\u2009WARN\u2009') @@ -37,9 +37,6 @@ const SUB = chalk.red('-') const h1 = chalk.cyanBright const hlValue = chalk.cyanBright const hlPkgId = chalk['whiteBright'] -const POSTINSTALL = hlValue('postinstall') -const PREINSTALL = hlValue(' preinstall') -const INSTALL = hlValue(' install') const EOL = '\n' @@ -515,175 +512,6 @@ test('prints summary correctly when the same package is specified both in option }) }) -test('groups lifecycle output', t => { - const output$ = toOutput$({ - context: { argv: ['install'] }, - reportingOptions: { outputMaxWidth: 79 }, - streamParser: createStreamParser(), - }) - - const pkgId = 'registry.npmjs.org/foo/1.0.0' - const wd = process.cwd() - - lifecycleLogger.debug({ - depPath: 'registry.npmjs.org/foo/1.0.0', - script: 'node foo', - stage: 'preinstall', - stdio: 'stdout', - wd, - }) - lifecycleLogger.debug({ - depPath: 'registry.npmjs.org/foo/1.0.0', - line: 'foo 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20', - stage: 'preinstall', - stdio: 'stdout', - wd, - }) - lifecycleLogger.debug({ - depPath: 'registry.npmjs.org/foo/1.0.0', - script: 'node foo', - stage: 'postinstall', - stdio: 'stdout', - wd, - }) - lifecycleLogger.debug({ - depPath: 'registry.npmjs.org/foo/1.0.0', - line: 'foo I', - stage: 'postinstall', - stdio: 'stdout', - wd, - }) - lifecycleLogger.debug({ - depPath: 'registry.npmjs.org/bar/1.0.0', - script: 'node bar', - stage: 'postinstall', - stdio: 'stdout', - wd, - }) - lifecycleLogger.debug({ - depPath: 'registry.npmjs.org/bar/1.0.0', - line: 'bar I', - stage: 'postinstall', - stdio: 'stdout', - wd, - }) - lifecycleLogger.debug({ - depPath: 'registry.npmjs.org/foo/1.0.0', - line: 'foo II', - stage: 'postinstall', - stdio: 'stdout', - wd, - }) - lifecycleLogger.debug({ - depPath: 'registry.npmjs.org/foo/1.0.0', - line: 'foo III', - stage: 'postinstall', - stdio: 'stdout', - wd, - }) - lifecycleLogger.debug({ - depPath: 'registry.npmjs.org/qar/1.0.0', - script: 'node qar', - stage: 'install', - stdio: 'stdout', - wd, - }) - lifecycleLogger.debug({ - depPath: 'registry.npmjs.org/qar/1.0.0', - exitCode: 0, - stage: 'install', - wd, - }) - lifecycleLogger.debug({ - depPath: 'registry.npmjs.org/foo/1.0.0', - exitCode: 0, - stage: 'postinstall', - wd, - }) - - t.plan(1) - - output$.skip(9).take(1).map(normalizeNewline).subscribe({ - complete: () => t.end(), - error: t.end, - next: output => { - t.equal(output, EOL + stripIndents` - registry.npmjs.org/foo/1.0.0 | ${PREINSTALL}$ node foo - registry.npmjs.org/foo/1.0.0 | ${PREINSTALL}: foo 0 1 2 3 4 5 6 7 8 9 - - registry.npmjs.org/foo/1.0.0 | ${POSTINSTALL}$ node foo - registry.npmjs.org/foo/1.0.0 | ${POSTINSTALL}: foo I - registry.npmjs.org/foo/1.0.0 | ${POSTINSTALL}: foo II - registry.npmjs.org/foo/1.0.0 | ${POSTINSTALL}: foo III - - registry.npmjs.org/bar/1.0.0 | ${POSTINSTALL}$ node bar - registry.npmjs.org/bar/1.0.0 | ${POSTINSTALL}: bar I - - registry.npmjs.org/qar/1.0.0 | ${INSTALL}$ node qar - registry.npmjs.org/qar/1.0.0 | ${INSTALL}: done - `) - }, - }) -}) - -// Many libs use stderr for logging, so showing all stderr adds not much value -test['skip']('prints lifecycle progress', t => { - const output$ = toOutput$({ - context: { argv: ['install'] }, - streamParser: createStreamParser(), - }) - - const wd = process.cwd() - - lifecycleLogger.debug({ - depPath: 'registry.npmjs.org/foo/1.0.0', - line: 'foo I', - script: 'postinstall', - stage: 'postinstall', - wd, - }) - lifecycleLogger.debug({ - depPath: 'registry.npmjs.org/bar/1.0.0', - line: 'bar I', - script: 'postinstall', - stage: 'postinstall', - wd, - }) - lifecycleLogger.debug({ - depPath: 'registry.npmjs.org/foo/1.0.0', - line: 'foo II', - script: 'postinstall', - stage: 'postinstall', - stdio: 'stderr', - wd, - }) - lifecycleLogger.debug({ - depPath: 'registry.npmjs.org/foo/1.0.0', - line: 'foo III', - script: 'postinstall', - stage: 'postinstall', - wd, - }) - - t.plan(1) - - const childOutputColor = chalk.grey - const childOutputError = chalk.red - - output$.skip(3).take(1).map(normalizeNewline).subscribe({ - complete: () => t.end(), - error: t.end, - next: output => { - t.equal(output, stripIndents` - Running ${POSTINSTALL} for ${hlPkgId('registry.npmjs.org/foo/1.0.0')}: ${childOutputColor('foo I')} - Running ${POSTINSTALL} for ${hlPkgId('registry.npmjs.org/foo/1.0.0')}! ${childOutputError('foo II')} - Running ${POSTINSTALL} for ${hlPkgId('registry.npmjs.org/foo/1.0.0')}: ${childOutputColor('foo III')} - Running ${POSTINSTALL} for ${hlPkgId('registry.npmjs.org/bar/1.0.0')}: ${childOutputColor('bar I')} - `) - }, - }) -}) - test('prints generic error', t => { const output$ = toOutput$({ context: { argv: ['install'] }, diff --git a/packages/default-reporter/test/reportingLifecycleScripts.ts b/packages/default-reporter/test/reportingLifecycleScripts.ts new file mode 100644 index 0000000000..002019963a --- /dev/null +++ b/packages/default-reporter/test/reportingLifecycleScripts.ts @@ -0,0 +1,574 @@ +import { lifecycleLogger } from '@pnpm/core-loggers' +import { toOutput$ } from '@pnpm/default-reporter' +import { createStreamParser } from '@pnpm/logger' +import chalk from 'chalk' +import { stripIndents } from 'common-tags' +import normalizeNewline = require('normalize-newline') +import path = require('path') +import test = require('tape') + +const hlValue = chalk.cyanBright +const hlPkgId = chalk['whiteBright'] + +const POSTINSTALL = hlValue('postinstall') +const PREINSTALL = hlValue('preinstall') +const INSTALL = hlValue('install') +const OUTPUT_INDENTATION = chalk.magentaBright('│') +const STATUS_INDENTATION = chalk.magentaBright('└─') +const STATUS_RUNNING = chalk.magentaBright('Running...') +const STATUS_DONE = chalk.magentaBright('Done in 1s') +const STATUS_FAILED = chalk.red('Failed in 1s') +const EOL = '\n' + +function replaceTimeWith1Sec (text: string) { + return text + .replace(/Done in [a-z0-9μ]+/g, 'Done in 1s') + .replace(/done in [a-z0-9μ]+/g, 'done in 1s') + .replace(/Failed in [a-z0-9μ]+/g, 'Failed in 1s') + .replace(/failed in [a-z0-9μ]+/g, 'failed in 1s') +} + +test('groups lifecycle output', t => { + const output$ = toOutput$({ + context: { argv: ['install'] }, + reportingOptions: { outputMaxWidth: 79 }, + streamParser: createStreamParser(), + }) + + lifecycleLogger.debug({ + depPath: 'packages/foo', + optional: false, + script: 'node foo', + stage: 'preinstall', + wd: 'packages/foo', + }) + lifecycleLogger.debug({ + depPath: 'packages/foo', + line: 'foo 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30', + stage: 'preinstall', + stdio: 'stdout', + wd: 'packages/foo', + }) + lifecycleLogger.debug({ + depPath: 'packages/foo', + optional: false, + script: 'node foo', + stage: 'postinstall', + wd: 'packages/foo', + }) + lifecycleLogger.debug({ + depPath: 'packages/foo', + line: 'foo I', + stage: 'postinstall', + stdio: 'stdout', + wd: 'packages/foo', + }) + lifecycleLogger.debug({ + depPath: 'packages/bar', + optional: false, + script: 'node bar', + stage: 'postinstall', + wd: 'packages/bar', + }) + lifecycleLogger.debug({ + depPath: 'packages/bar', + line: 'bar I', + stage: 'postinstall', + stdio: 'stdout', + wd: 'packages/bar', + }) + lifecycleLogger.debug({ + depPath: 'packages/foo', + line: 'foo II', + stage: 'postinstall', + stdio: 'stdout', + wd: 'packages/foo', + }) + lifecycleLogger.debug({ + depPath: 'packages/foo', + line: 'foo III', + stage: 'postinstall', + stdio: 'stdout', + wd: 'packages/foo', + }) + lifecycleLogger.debug({ + depPath: 'packages/qar', + optional: false, + script: 'node qar', + stage: 'install', + wd: 'packages/qar', + }) + lifecycleLogger.debug({ + depPath: 'packages/qar', + exitCode: 0, + optional: false, + stage: 'install', + wd: 'packages/qar' + }) + lifecycleLogger.debug({ + depPath: 'packages/foo', + exitCode: 0, + optional: false, + stage: 'postinstall', + wd: 'packages/foo' + }) + + t.plan(1) + + output$.skip(9).take(1).map(normalizeNewline).subscribe({ + complete: () => t.end(), + error: t.end, + next: (output: string) => { + t.equal(replaceTimeWith1Sec(output), stripIndents` + packages/foo ${PREINSTALL}$ node foo + ${OUTPUT_INDENTATION} foo 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 + ${STATUS_INDENTATION} ${STATUS_RUNNING} + packages/foo ${POSTINSTALL}$ node foo + ${OUTPUT_INDENTATION} foo I + ${OUTPUT_INDENTATION} foo II + ${OUTPUT_INDENTATION} foo III + ${STATUS_INDENTATION} ${STATUS_RUNNING} + packages/bar ${POSTINSTALL}$ node bar + ${OUTPUT_INDENTATION} bar I + ${STATUS_INDENTATION} ${STATUS_RUNNING} + packages/qar ${INSTALL}$ node qar + ${STATUS_INDENTATION} ${STATUS_DONE} + `) + }, + }) +}) + +test('groups lifecycle output when append-only is used', t => { + const output$ = toOutput$({ + context: { argv: ['install'] }, + reportingOptions: { + appendOnly: true, + outputMaxWidth: 79, + }, + streamParser: createStreamParser(), + }) + + lifecycleLogger.debug({ + depPath: 'packages/foo', + optional: false, + script: 'node foo', + stage: 'preinstall', + wd: 'packages/foo', + }) + lifecycleLogger.debug({ + depPath: 'packages/foo', + line: 'foo 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30', + stage: 'preinstall', + stdio: 'stdout', + wd: 'packages/foo', + }) + lifecycleLogger.debug({ + depPath: 'packages/foo', + exitCode: 1, + optional: true, + stage: 'preinstall', + wd: 'packages/foo', + }) + lifecycleLogger.debug({ + depPath: 'packages/foo', + optional: false, + script: 'node foo', + stage: 'postinstall', + wd: 'packages/foo', + }) + lifecycleLogger.debug({ + depPath: 'packages/foo', + line: 'foo I', + stage: 'postinstall', + stdio: 'stdout', + wd: 'packages/foo', + }) + lifecycleLogger.debug({ + depPath: 'packages/bar', + optional: false, + script: 'node bar', + stage: 'postinstall', + wd: 'packages/bar', + }) + lifecycleLogger.debug({ + depPath: 'packages/bar', + line: 'bar I', + stage: 'postinstall', + stdio: 'stdout', + wd: 'packages/bar', + }) + lifecycleLogger.debug({ + depPath: 'packages/foo', + line: 'foo II', + stage: 'postinstall', + stdio: 'stdout', + wd: 'packages/foo', + }) + lifecycleLogger.debug({ + depPath: 'packages/foo', + line: 'foo III', + stage: 'postinstall', + stdio: 'stdout', + wd: 'packages/foo', + }) + lifecycleLogger.debug({ + depPath: 'packages/qar', + optional: false, + script: 'node qar', + stage: 'install', + wd: 'packages/qar', + }) + lifecycleLogger.debug({ + depPath: 'packages/qar', + exitCode: 0, + optional: false, + stage: 'install', + wd: 'packages/qar' + }) + lifecycleLogger.debug({ + depPath: 'packages/foo', + exitCode: 0, + optional: false, + stage: 'postinstall', + wd: 'packages/foo' + }) + + t.plan(1) + + let allOutputs = [] as string[] + + output$.take(11).map(normalizeNewline).subscribe({ + complete: () => { + t.equal(allOutputs.join(EOL), stripIndents` + packages/foo ${PREINSTALL}$ node foo + packages/foo ${PREINSTALL}: foo 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 + packages/foo ${PREINSTALL}: Failed + packages/foo ${POSTINSTALL}$ node foo + packages/foo ${POSTINSTALL}: foo I + packages/bar ${POSTINSTALL}$ node bar + packages/bar ${POSTINSTALL}: bar I + packages/foo ${POSTINSTALL}: foo II + packages/foo ${POSTINSTALL}: foo III + packages/qar ${INSTALL}$ node qar + packages/qar ${INSTALL}: Done + `) + t.end() + }, + error: t.end, + next: (output: string) => { allOutputs.push(output) }, + }) +}) + +test('collapse lifecycle output when it has too many lines', t => { + const output$ = toOutput$({ + context: { argv: ['install'] }, + reportingOptions: { outputMaxWidth: 79 }, + streamParser: createStreamParser(), + }) + + lifecycleLogger.debug({ + depPath: 'packages/foo', + optional: false, + script: 'node foo', + stage: 'postinstall', + wd: 'packages/foo', + }) + for (let i = 0; i < 100; i++) { + lifecycleLogger.debug({ + depPath: 'packages/foo', + line: `foo ${i}`, + stage: 'postinstall', + stdio: 'stdout', + wd: 'packages/foo', + }) + } + lifecycleLogger.debug({ + depPath: 'packages/foo', + exitCode: 0, + optional: false, + stage: 'postinstall', + wd: 'packages/foo' + }) + + t.plan(1) + + output$.skip(101).take(1).map(normalizeNewline).subscribe({ + complete: () => t.end(), + error: t.end, + next: (output: string) => { + t.equal(replaceTimeWith1Sec(output), stripIndents` + packages/foo ${POSTINSTALL}$ node foo + [90 lines collapsed] + ${OUTPUT_INDENTATION} foo 90 + ${OUTPUT_INDENTATION} foo 91 + ${OUTPUT_INDENTATION} foo 92 + ${OUTPUT_INDENTATION} foo 93 + ${OUTPUT_INDENTATION} foo 94 + ${OUTPUT_INDENTATION} foo 95 + ${OUTPUT_INDENTATION} foo 96 + ${OUTPUT_INDENTATION} foo 97 + ${OUTPUT_INDENTATION} foo 98 + ${OUTPUT_INDENTATION} foo 99 + ${STATUS_INDENTATION} ${STATUS_DONE} + `) + }, + }) +}) + +test('collapses lifecycle output of packages from node_modules', t => { + const output$ = toOutput$({ + context: { argv: ['install'] }, + reportingOptions: { outputMaxWidth: 79 }, + streamParser: createStreamParser(), + }) + + const wdOfFoo = path.resolve(process.cwd(), 'node_modules', '.registry.npmjs.org', 'foo', '1.0.0', 'node_modules', 'foo') + const wdOfBar = path.resolve(process.cwd(), 'node_modules', '.registry.npmjs.org', 'bar', '1.0.0', 'node_modules', 'bar') + const wdOfQar = path.resolve(process.cwd(), 'node_modules', '.registry.npmjs.org', 'qar', '1.0.0', 'node_modules', 'qar') + + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/foo/1.0.0', + optional: false, + script: 'node foo', + stage: 'preinstall', + wd: wdOfFoo, + }) + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/foo/1.0.0', + line: 'foo 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20', + stage: 'preinstall', + stdio: 'stdout', + wd: wdOfFoo, + }) + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/foo/1.0.0', + optional: false, + script: 'node foo', + stage: 'postinstall', + stdio: 'stdout', + wd: wdOfFoo, + }) + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/foo/1.0.0', + line: 'foo I', + stage: 'postinstall', + stdio: 'stdout', + wd: wdOfFoo, + }) + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/bar/1.0.0', + optional: false, + script: 'node bar', + stage: 'postinstall', + wd: wdOfBar, + }) + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/bar/1.0.0', + line: 'bar I', + stage: 'postinstall', + stdio: 'stdout', + wd: wdOfBar, + }) + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/foo/1.0.0', + line: 'foo II', + stage: 'postinstall', + stdio: 'stdout', + wd: wdOfFoo, + }) + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/foo/1.0.0', + line: 'foo III', + stage: 'postinstall', + stdio: 'stdout', + wd: wdOfFoo, + }) + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/qar/1.0.0', + optional: false, + script: 'node qar', + stage: 'install', + wd: wdOfQar, + }) + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/qar/1.0.0', + exitCode: 0, + optional: false, + stage: 'install', + wd: wdOfQar, + }) + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/foo/1.0.0', + exitCode: 0, + optional: false, + stage: 'postinstall', + wd: wdOfFoo, + }) + + t.plan(1) + + output$.skip(5).take(1).map(normalizeNewline).subscribe({ + complete: () => t.end(), + error: t.end, + next: (output: string) => { + t.equal(replaceTimeWith1Sec(output), stripIndents` + ${chalk.gray('node_modules/.registry.npmjs.org/foo/1.0.0/node_modules/')}foo: Running preinstall script... + ${chalk.gray('node_modules/.registry.npmjs.org/foo/1.0.0/node_modules/')}foo: Running postinstall script, done in 1s + ${chalk.gray('node_modules/.registry.npmjs.org/bar/1.0.0/node_modules/')}bar: Running postinstall script... + ${chalk.gray('node_modules/.registry.npmjs.org/qar/1.0.0/node_modules/')}qar: Running install script, done in 1s + `) + }, + }) +}) + +test('output of failed optional dependency is not shown', t => { + const output$ = toOutput$({ + context: { argv: ['install'] }, + reportingOptions: { outputMaxWidth: 79 }, + streamParser: createStreamParser(), + }) + + const wd = path.resolve(process.cwd(), 'node_modules', '.registry.npmjs.org', 'foo', '1.0.0', 'node_modules', 'foo') + + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/foo/1.0.0', + optional: true, + script: 'node foo', + stage: 'install', + wd: wd, + }) + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/foo/1.0.0', + line: 'foo 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20', + stage: 'install', + stdio: 'stdout', + wd, + }) + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/foo/1.0.0', + exitCode: 1, + optional: true, + stage: 'install', + wd, + }) + + t.plan(1) + + output$.skip(1).take(1).map(normalizeNewline).subscribe({ + complete: () => t.end(), + error: t.end, + next: (output: string) => { + t.equal(replaceTimeWith1Sec(output), stripIndents` + ${chalk.gray('node_modules/.registry.npmjs.org/foo/1.0.0/node_modules/')}foo: Running install script, failed in 1s (skipped as optional) + `) + }, + }) +}) + +test('output of failed non-optional dependency is printed', t => { + const output$ = toOutput$({ + context: { argv: ['install'] }, + reportingOptions: { outputMaxWidth: 79 }, + streamParser: createStreamParser(), + }) + + const wd = path.resolve(process.cwd(), 'node_modules', '.registry.npmjs.org', 'foo', '1.0.0', 'node_modules', 'foo') + + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/foo/1.0.0', + optional: false, + script: 'node foo', + stage: 'install', + wd: wd, + }) + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/foo/1.0.0', + line: 'foo 0 1 2 3 4 5 6 7 8 9', + stage: 'install', + stdio: 'stdout', + wd, + }) + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/foo/1.0.0', + exitCode: 1, + optional: false, + stage: 'install', + wd, + }) + + t.plan(1) + + output$.skip(1).take(1).map(normalizeNewline).subscribe({ + complete: () => t.end(), + error: t.end, + next: (output: string) => { + t.equal(replaceTimeWith1Sec(output), stripIndents` + ${chalk.gray('node_modules/.registry.npmjs.org/foo/1.0.0/node_modules/')}foo: Running install script, failed in 1s + .../foo/1.0.0/node_modules/foo ${INSTALL}$ node foo + ${OUTPUT_INDENTATION} foo 0 1 2 3 4 5 6 7 8 9 + ${STATUS_INDENTATION} ${STATUS_FAILED} + `) + }, + }) +}) + +// Many libs use stderr for logging, so showing all stderr adds not much value +test['skip']('prints lifecycle progress', t => { + const output$ = toOutput$({ + context: { argv: ['install'] }, + streamParser: createStreamParser(), + }) + + const wd = process.cwd() + + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/foo/1.0.0', + line: 'foo I', + optional: false, + script: 'postinstall', + stage: 'postinstall', + wd, + }) + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/bar/1.0.0', + line: 'bar I', + optional: false, + script: 'postinstall', + stage: 'postinstall', + wd, + }) + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/foo/1.0.0', + line: 'foo II', + script: 'postinstall', + stage: 'postinstall', + stdio: 'stderr', + wd, + }) + lifecycleLogger.debug({ + depPath: 'registry.npmjs.org/foo/1.0.0', + line: 'foo III', + optional: false, + script: 'postinstall', + stage: 'postinstall', + wd, + }) + + t.plan(1) + + const childOutputColor = chalk.grey + const childOutputError = chalk.red + + output$.skip(3).take(1).map(normalizeNewline).subscribe({ + complete: () => t.end(), + error: t.end, + next: output => { + t.equal(output, stripIndents` + Running ${POSTINSTALL} for ${hlPkgId('registry.npmjs.org/foo/1.0.0')}: ${childOutputColor('foo I')} + Running ${POSTINSTALL} for ${hlPkgId('registry.npmjs.org/foo/1.0.0')}! ${childOutputError('foo II')} + Running ${POSTINSTALL} for ${hlPkgId('registry.npmjs.org/foo/1.0.0')}: ${childOutputColor('foo III')} + Running ${POSTINSTALL} for ${hlPkgId('registry.npmjs.org/bar/1.0.0')}: ${childOutputColor('bar I')} + `) + }, + }) +}) diff --git a/packages/default-reporter/typings/local.d.ts b/packages/default-reporter/typings/local.d.ts index 8abe2e10b2..b68175eb1a 100644 --- a/packages/default-reporter/typings/local.d.ts +++ b/packages/default-reporter/typings/local.d.ts @@ -43,7 +43,7 @@ declare module 'normalize-path' { export = normalize; } -declare module 'string.prototype.padstart' { - function padStart (s: string, targetLength: number, padString?: string): string; - export = padStart; +declare module 'pretty-time' { + function prettyTime (time: [number, number]): string; + export = prettyTime; } diff --git a/packages/headless/src/index.ts b/packages/headless/src/index.ts index 7989e79406..cc16463747 100644 --- a/packages/headless/src/index.ts +++ b/packages/headless/src/index.ts @@ -123,6 +123,7 @@ export default async (opts: HeadlessOptions) => { const scriptsOpts = { depPath: importer.prefix, + optional: false, pkgRoot: importer.prefix, rawNpmConfig: opts.rawNpmConfig, rootNodeModulesDir: importer.modulesDir, @@ -305,6 +306,7 @@ export default async (opts: HeadlessOptions) => { const scriptsOpts = { depPath: importer.prefix, + optional: false, pkgRoot: importer.prefix, rawNpmConfig: opts.rawNpmConfig, rootNodeModulesDir: importer.modulesDir, diff --git a/packages/headless/src/runDependenciesScripts.ts b/packages/headless/src/runDependenciesScripts.ts index 4a6af403ad..101f550883 100644 --- a/packages/headless/src/runDependenciesScripts.ts +++ b/packages/headless/src/runDependenciesScripts.ts @@ -53,6 +53,7 @@ export default async ( try { const hasSideEffects = await runPostinstallHooks({ depPath, + optional: depNode.optional, pkgRoot: depNode.peripheralLocation, prepare: depNode.prepare, rawNpmConfig: opts.rawNpmConfig, diff --git a/packages/lifecycle/src/index.ts b/packages/lifecycle/src/index.ts index cdd5004765..9e86d947d8 100644 --- a/packages/lifecycle/src/index.ts +++ b/packages/lifecycle/src/index.ts @@ -10,10 +10,11 @@ function noop () {} // tslint:disable-line:no-empty export async function runPostinstallHooks ( opts: { depPath: string, - rootNodeModulesDir: string, - rawNpmConfig: object, + optional?: boolean, pkgRoot: string, prepare?: boolean, + rawNpmConfig: object, + rootNodeModulesDir: string, unsafePerm: boolean, }, ): Promise { @@ -46,16 +47,19 @@ export default async function runLifecycleHook ( pkg: PackageJson, opts: { depPath: string, - rootNodeModulesDir: string, - rawNpmConfig: object, + optional?: boolean, pkgRoot: string, + rawNpmConfig: object, + rootNodeModulesDir: string, stdio?: string, unsafePerm: boolean, }, ) { + const optional = opts.optional === true if (opts.stdio !== 'inherit') { lifecycleLogger.debug({ depPath: opts.depPath, + optional, script: pkg.scripts![stage], stage, wd: opts.pkgRoot, @@ -101,6 +105,7 @@ export default async function runLifecycleHook ( lifecycleLogger.debug({ depPath: opts.depPath, exitCode: code, + optional, stage, wd: opts.pkgRoot, }) diff --git a/packages/lifecycle/test/index.ts b/packages/lifecycle/test/index.ts index 4dd254c83e..2547da5746 100644 --- a/packages/lifecycle/test/index.ts +++ b/packages/lifecycle/test/index.ts @@ -11,10 +11,11 @@ test('runLifecycleHook()', async (t) => { const pkgRoot = path.join(fixtures, 'simple') const pkg = require(path.join(pkgRoot, 'package.json')) await runLifecycleHook('postinstall', pkg, { - rootNodeModulesDir, depPath: '/simple/1.0.0', - rawNpmConfig: {}, + optional: false, pkgRoot, + rawNpmConfig: {}, + rootNodeModulesDir, unsafePerm: true, }) @@ -28,10 +29,11 @@ test('runPostinstallHooks()', async (t) => { const pkg = require(path.join(pkgRoot, 'package.json')) rimraf.sync(path.join(pkgRoot, 'output.json')) await runPostinstallHooks({ - rootNodeModulesDir, depPath: '/with-many-scripts/1.0.0', - rawNpmConfig: {}, + optional: false, pkgRoot, + rawNpmConfig: {}, + rootNodeModulesDir, unsafePerm: true, }) @@ -45,11 +47,12 @@ test('runPostinstallHooks() with prepare = true', async (t) => { const pkg = require(path.join(pkgRoot, 'package.json')) rimraf.sync(path.join(pkgRoot, 'output.json')) await runPostinstallHooks({ - rootNodeModulesDir, depPath: '/with-many-scripts/1.0.0', - rawNpmConfig: {}, - prepare: true, + optional: false, pkgRoot, + prepare: true, + rawNpmConfig: {}, + rootNodeModulesDir, unsafePerm: true, }) diff --git a/packages/supi/src/install/index.ts b/packages/supi/src/install/index.ts index ea11f78bbd..24841273dc 100644 --- a/packages/supi/src/install/index.ts +++ b/packages/supi/src/install/index.ts @@ -329,6 +329,7 @@ export async function mutateModules ( const scriptsOpts = { depPath: importer.prefix, + optional: false, pkgRoot: importer.prefix, rawNpmConfig: opts.rawNpmConfig, rootNodeModulesDir: importer.modulesDir, @@ -380,6 +381,7 @@ export async function mutateModules ( const scriptsOpts = { depPath: importer.prefix, + optional: false, pkgRoot: importer.prefix, rawNpmConfig: opts.rawNpmConfig, rootNodeModulesDir: importer.modulesDir, @@ -853,6 +855,7 @@ async function installInContext ( try { const hasSideEffects = await runPostinstallHooks({ depPath: pkg.absolutePath, + optional: pkg.optional, pkgRoot: pkg.peripheralLocation, prepare: pkg.prepare, rawNpmConfig: opts.rawNpmConfig, diff --git a/packages/supi/src/rebuild/index.ts b/packages/supi/src/rebuild/index.ts index 005c364825..a529aa24b7 100644 --- a/packages/supi/src/rebuild/index.ts +++ b/packages/supi/src/rebuild/index.ts @@ -161,6 +161,7 @@ async function runLifecycleHooksInDir ( ) { const scriptsOpts = { depPath: prefix, + optional: false, pkgRoot: prefix, rawNpmConfig: opts.rawNpmConfig, rootNodeModulesDir: opts.rootNodeModulesDir, @@ -274,6 +275,7 @@ async function _rebuild ( try { await runPostinstallHooks({ depPath: depAbsolutePath, + optional: pkgSnapshot.optional === true, pkgRoot: path.join(modules, `.${depAbsolutePath}`, 'node_modules', pkgInfo.name), prepare: pkgSnapshot.prepare, rawNpmConfig: opts.rawNpmConfig, diff --git a/shrinkwrap.yaml b/shrinkwrap.yaml index 5da3c7a383..0dffa7a2ab 100644 --- a/shrinkwrap.yaml +++ b/shrinkwrap.yaml @@ -112,12 +112,12 @@ importers: most: /most/1.7.3/most@1.7.3 normalize-path: 3.0.0 pretty-bytes: 5.1.0 + pretty-time: 1.1.0 ramda: 0.26.1 right-pad: 1.0.1 semver: 5.6.0 stacktracey: 1.2.106 string-length: 2.0.0 - string.prototype.padstart: 3.0.0 strip-ansi: 5.0.0 zen-push: 0.2.1 devDependencies: @@ -160,13 +160,13 @@ importers: normalize-newline: 3.0.0 normalize-path: 3.0.0 pretty-bytes: 5.1.0 + pretty-time: 1.1.0 ramda: 0.26.1 right-pad: 1.0.1 rimraf: 2.6.2 semver: 5.6.0 stacktracey: 1.2.106 string-length: 2.0.0 - string.prototype.padstart: 3.0.0 strip-ansi: 5.0.0 tape: 4.9.1 ts-node: 6.2.0 @@ -7982,6 +7982,12 @@ packages: node: '>=0.10.0' resolution: integrity: sha1-QlfCVt8/sLRR1q/6qwIYhBJpgdw= + /pretty-time/1.1.0: + dev: false + engines: + node: '>=4' + resolution: + integrity: sha512-28iF6xPQrP8Oa6uxE6a1biz+lWeTOAPKggvjB8HAs6nVMKZwf5bG++632Dx614hIWgUPkgivRfG+a8uAXGTIbA== /printable-characters/1.0.42: dev: false resolution: @@ -9191,16 +9197,6 @@ packages: node: '>= 0.4' resolution: integrity: sha1-86rvfBcZ8XDF6rHDK/eA2W4h8vA= - /string.prototype.padstart/3.0.0: - dependencies: - define-properties: 1.1.3 - es-abstract: 1.12.0 - function-bind: 1.1.1 - dev: false - engines: - node: '>= 0.4' - resolution: - integrity: sha1-W8+tOfRkm7LQMSkuGbzwtRDUskI= /string.prototype.trim/1.1.2: dependencies: define-properties: 1.1.3