From b9c3a1908c9787ca3190f8f89ee6d39d23a258c8 Mon Sep 17 00:00:00 2001 From: Zoltan Kochan Date: Fri, 4 Jan 2019 01:49:09 +0200 Subject: [PATCH] feat(reporting): progress reporting per workspace package close #1135 PR #1586 --- packages/core-loggers/src/all.ts | 2 +- packages/core-loggers/src/cliLogger.ts | 7 - .../src/fetchingProgressLogger.ts | 19 + packages/core-loggers/src/index.ts | 6 +- packages/core-loggers/src/progressLogger.ts | 34 +- packages/core-loggers/src/stageLogger.ts | 12 +- packages/default-reporter/src/index.ts | 10 +- .../src/reporterForClient/index.ts | 7 +- .../reportBigTarballsProgress.ts | 14 +- .../src/reporterForClient/reportProgress.ts | 240 ++++++---- .../default-reporter/src/reporterForServer.ts | 8 +- packages/default-reporter/test/index.ts | 318 +------------ .../test/reportingProgress.ts | 425 ++++++++++++++++++ packages/headless/src/index.ts | 29 +- packages/headless/test/index.ts | 39 +- .../package-requester/src/packageRequester.ts | 24 +- packages/pnpm/src/cmd/recursive/index.ts | 2 - packages/pnpm/src/main.ts | 3 - packages/resolve-dependencies/src/index.ts | 2 + .../src/resolveDependencies.ts | 24 +- packages/supi/src/install/index.ts | 13 +- packages/supi/src/install/link.ts | 12 +- packages/supi/test/install/misc.ts | 28 +- 23 files changed, 746 insertions(+), 532 deletions(-) delete mode 100644 packages/core-loggers/src/cliLogger.ts create mode 100644 packages/core-loggers/src/fetchingProgressLogger.ts create mode 100644 packages/default-reporter/test/reportingProgress.ts diff --git a/packages/core-loggers/src/all.ts b/packages/core-loggers/src/all.ts index 5cb7632dc4..779b936d73 100644 --- a/packages/core-loggers/src/all.ts +++ b/packages/core-loggers/src/all.ts @@ -1,5 +1,5 @@ -export * from './cliLogger' export * from './deprecationLogger' +export * from './fetchingProgressLogger' export * from './hookLogger' export * from './importingLogger' export * from './installCheckLogger' diff --git a/packages/core-loggers/src/cliLogger.ts b/packages/core-loggers/src/cliLogger.ts deleted file mode 100644 index 92ad9ed0e1..0000000000 --- a/packages/core-loggers/src/cliLogger.ts +++ /dev/null @@ -1,7 +0,0 @@ -import baseLogger, { - LogBase, -} from '@pnpm/logger' - -export const cliLogger = baseLogger<'command_done'>('cli') - -export type CliLog = {name: 'pnpm:cli'} & LogBase & {message: 'command_done'} diff --git a/packages/core-loggers/src/fetchingProgressLogger.ts b/packages/core-loggers/src/fetchingProgressLogger.ts new file mode 100644 index 0000000000..d05ba94147 --- /dev/null +++ b/packages/core-loggers/src/fetchingProgressLogger.ts @@ -0,0 +1,19 @@ +import baseLogger, { + LogBase, + Logger, +} from '@pnpm/logger' + +export const fetchingProgressLogger = baseLogger('fetching-progress') as Logger // tslint:disable-line + +export type FetchingProgressMessage = { + attempt: number, + packageId: string, + size: number | null, + status: 'started', +} | { + downloaded: number, + packageId: string, + status: 'in_progress', +} + +export type FetchingProgressLog = {name: 'pnpm:fetching-progress'} & LogBase & FetchingProgressMessage diff --git a/packages/core-loggers/src/index.ts b/packages/core-loggers/src/index.ts index ebb4e130ae..b6f3151edf 100644 --- a/packages/core-loggers/src/index.ts +++ b/packages/core-loggers/src/index.ts @@ -1,8 +1,8 @@ export * from './all' import { - CliLog, DeprecationLog, + FetchingProgressLog, HookLog, ImportingLog, InstallCheckLog, @@ -19,8 +19,8 @@ import { SummaryLog, } from './all' -export type Log = CliLog - | DeprecationLog +export type Log = DeprecationLog + | FetchingProgressLog | HookLog | ImportingLog | InstallCheckLog diff --git a/packages/core-loggers/src/progressLogger.ts b/packages/core-loggers/src/progressLogger.ts index f7e96c0d81..4b9897f91e 100644 --- a/packages/core-loggers/src/progressLogger.ts +++ b/packages/core-loggers/src/progressLogger.ts @@ -5,38 +5,10 @@ import baseLogger, { export const progressLogger = baseLogger('progress') as Logger // tslint:disable-line -export interface LoggedPkg { - rawSpec: string, - name?: string, // sometimes known for the root dependency on named installation - dependentId?: string, -} - export type ProgressMessage = { - pkgId: string, - pkg: LoggedPkg, - status: 'resolved', -} | { - pkg: LoggedPkg, - status: 'error', -} | { - pkgId: string, - status: 'fetching_started', - size: number | null, - attempt: number, -} | { - pkgId: string, - status: 'fetching_progress', - downloaded: number, -} | { - pkg: LoggedPkg, - status: 'installing', -} | { - status: 'downloaded_manifest', - pkgId: string, - pkgVersion: string, -} | { - pkgId: string, - status: 'fetched' | 'found_in_store' | 'resolving_content', + packageId: string, + requester: string, + status: 'fetched' | 'found_in_store' | 'resolved', } export type ProgressLog = {name: 'pnpm:progress'} & LogBase & ProgressMessage diff --git a/packages/core-loggers/src/stageLogger.ts b/packages/core-loggers/src/stageLogger.ts index ba9374a5f6..24f1059988 100644 --- a/packages/core-loggers/src/stageLogger.ts +++ b/packages/core-loggers/src/stageLogger.ts @@ -2,6 +2,14 @@ import baseLogger, { LogBase, } from '@pnpm/logger' -export const stageLogger = baseLogger<'resolution_started' | 'resolution_done' | 'importing_started' | 'importing_done' | 'recursive_importing_done'>('stage') +export const stageLogger = baseLogger('stage') -export type StageLog = {name: 'pnpm:stage'} & LogBase & {message: 'resolution_started' | 'resolution_done' | 'importing_started' | 'importing_done'} +export type StageMessage = { + prefix: string, + stage: 'resolution_started' + | 'resolution_done' + | 'importing_started' + | 'importing_done', +} + +export type StageLog = {name: 'pnpm:stage'} & LogBase & StageMessage diff --git a/packages/default-reporter/src/index.ts b/packages/default-reporter/src/index.ts index 40e19c64d2..d5ac56d157 100644 --- a/packages/default-reporter/src/index.ts +++ b/packages/default-reporter/src/index.ts @@ -70,6 +70,7 @@ export function toOutput$ ( }, ): most.Stream { opts = opts || {} + const fetchingProgressPushStream = new PushStream() const progressPushStream = new PushStream() const stagePushStream = new PushStream() const deprecationPushStream = new PushStream() @@ -81,7 +82,6 @@ export function toOutput$ ( const rootPushStream = new PushStream() const packageJsonPushStream = new PushStream() const linkPushStream = new PushStream() - const cliPushStream = new PushStream() const otherPushStream = new PushStream() const hookPushStream = new PushStream() const skippedOptionalDependencyPushStream = new PushStream() @@ -89,6 +89,9 @@ export function toOutput$ ( setTimeout(() => { // setTimeout is a workaround for a strange bug in most https://github.com/cujojs/most/issues/491 opts.streamParser['on']('data', (log: logs.Log) => { switch (log.name) { + case 'pnpm:fetching-progress': + fetchingProgressPushStream.next(log) + break case 'pnpm:progress': progressPushStream.next(log) break @@ -122,9 +125,6 @@ export function toOutput$ ( case 'pnpm:link': linkPushStream.next(log) break - case 'pnpm:cli': - cliPushStream.next(log) - break case 'pnpm:hook': hookPushStream.next(log) break @@ -143,8 +143,8 @@ export function toOutput$ ( }) }, 0) const log$ = { - cli: most.from(cliPushStream.observable), deprecation: most.from(deprecationPushStream.observable), + fetchingProgress: most.from(fetchingProgressPushStream.observable), hook: most.from(hookPushStream.observable), installCheck: most.from(installCheckPushStream.observable), lifecycle: most.from(lifecyclePushStream.observable), diff --git a/packages/default-reporter/src/reporterForClient/index.ts b/packages/default-reporter/src/reporterForClient/index.ts index 71c00890cd..2acc056985 100644 --- a/packages/default-reporter/src/reporterForClient/index.ts +++ b/packages/default-reporter/src/reporterForClient/index.ts @@ -15,6 +15,7 @@ import reportSummary from './reportSummary' export default function ( log$: { + fetchingProgress: most.Stream, progress: most.Stream, stage: most.Stream, deprecation: most.Stream, @@ -27,7 +28,6 @@ export default function ( packageJson: most.Stream, link: most.Stream, other: most.Stream, - cli: most.Stream, hook: most.Stream, scope: most.Stream, skippedOptionalDependency: most.Stream, @@ -46,7 +46,10 @@ export default function ( const cwd = opts.pnpmConfigs && opts.pnpmConfigs.prefix || process.cwd() const outputs: Array>> = [ - reportProgress(log$, opts), + reportProgress(log$, { + cwd, + throttleProgress: opts.throttleProgress, + }), reportLifecycleScripts(log$, { appendOnly: opts.appendOnly, cwd, diff --git a/packages/default-reporter/src/reporterForClient/reportBigTarballsProgress.ts b/packages/default-reporter/src/reporterForClient/reportBigTarballsProgress.ts index f33b939076..6750113166 100644 --- a/packages/default-reporter/src/reporterForClient/reportBigTarballsProgress.ts +++ b/packages/default-reporter/src/reporterForClient/reportBigTarballsProgress.ts @@ -1,4 +1,4 @@ -import { ProgressLog } from '@pnpm/core-loggers' +import { FetchingProgressLog } from '@pnpm/core-loggers' import most = require('most') import prettyBytes = require('pretty-bytes') import { @@ -10,11 +10,11 @@ const BIG_TARBALL_SIZE = 1024 * 1024 * 5 // 5 MB export default ( log$: { - progress: most.Stream, + fetchingProgress: most.Stream, }, ) => { - return log$.progress - .filter((log) => log.status === 'fetching_started' && + return log$.fetchingProgress + .filter((log) => log.status === 'started' && typeof log.size === 'number' && log.size >= BIG_TARBALL_SIZE && // When retrying the download, keep the existing progress line. // Fixing issue: https://github.com/pnpm/pnpm/issues/1013 @@ -22,8 +22,8 @@ export default ( ) .map((startedLog) => { const size = prettyBytes(startedLog['size']) - return log$.progress - .filter((log) => log.status === 'fetching_progress' && log.pkgId === startedLog['pkgId']) + return log$.fetchingProgress + .filter((log) => log.status === 'in_progress' && log.packageId === startedLog['packageId']) .map((log) => log['downloaded']) .startWith(0) .map((downloadedRaw) => { @@ -31,7 +31,7 @@ export default ( const downloaded = prettyBytes(downloadedRaw) return { fixed: !done, - msg: `Downloading ${hlPkgId(startedLog['pkgId'])}: ${hlValue(downloaded)}/${hlValue(size)}${done ? ', done' : ''}`, + msg: `Downloading ${hlPkgId(startedLog['packageId'])}: ${hlValue(downloaded)}/${hlValue(size)}${done ? ', done' : ''}`, } }) }) diff --git a/packages/default-reporter/src/reporterForClient/reportProgress.ts b/packages/default-reporter/src/reporterForClient/reportProgress.ts index 25466c7e5f..05abb4b9f5 100644 --- a/packages/default-reporter/src/reporterForClient/reportProgress.ts +++ b/packages/default-reporter/src/reporterForClient/reportProgress.ts @@ -1,100 +1,172 @@ -import { CliLog, ProgressLog, StageLog } from '@pnpm/core-loggers' +import { ProgressLog, StageLog } from '@pnpm/core-loggers' +import PushStream from '@zkochan/zen-push' import most = require('most') -import R = require('ramda') import { hlValue } from './outputConstants' +import { zoomOut } from './utils/zooming' + +type ProgressStats = { + fetched: number, + resolved: number, + reused: number, +} + +type ModulesInstallProgress = { + importingDone$: most.Stream, + progress$: most.Stream, + requirer: string, +} export default ( log$: { progress: most.Stream, - cli: most.Stream, stage: most.Stream, }, opts: { - cmd: string, - isRecursive: boolean, + cwd: string, throttleProgress?: number, }, ) => { - const resolutionDone$ = opts.isRecursive - ? most.never() - : log$.stage - .filter((log) => log.message === 'resolution_done') + const progressOutput = typeof opts.throttleProgress === 'number' && opts.throttleProgress > 0 + ? throttledProgressOutput.bind(null, opts.throttleProgress) + : nonThrottledProgressOutput - const resolvingContentLog$ = log$.progress - .filter((log) => log.status === 'resolving_content') - .scan(R.inc, 0) - .skip(1) - .until(resolutionDone$) + return getModulesInstallProgress$(log$.stage, log$.progress) + .map(({ importingDone$, progress$, requirer }: ModulesInstallProgress) => { + const output$ = progressOutput(importingDone$, progress$) - const fedtchedLog$ = log$.progress - .filter((log) => log.status === 'fetched') - .scan(R.inc, 0) - - const foundInStoreLog$ = log$.progress - .filter((log) => log.status === 'found_in_store') - .scan(R.inc, 0) - - function createStatusMessage (resolving: number, fetched: number, foundInStore: number, importingDone: boolean) { - const msg = `Resolving: total ${hlValue(resolving.toString())}, reused ${hlValue(foundInStore.toString())}, downloaded ${hlValue(fetched.toString())}` - if (importingDone) { - return { - done: true, - fixed: false, - msg: `${msg}, done`, + if (requirer === opts.cwd) { + return output$ } - } - return { - fixed: true, - msg, - } - } - - const importingDone$ = (() => { - if (opts.cmd === 'link') { - return most.of(false) - } - const stageToWaitFor = opts.isRecursive ? 'recursive_importing_done' : 'importing_done' - return log$.stage - .filter((log) => log.message === stageToWaitFor) - .constant(true) - .take(1) - .startWith(false) - .multicast() - })() - - if (typeof opts.throttleProgress === 'number' && opts.throttleProgress > 0) { - const resolutionStarted$ = log$.stage - .filter((log) => log.message === 'resolution_started' || log.message === 'importing_started').take(1) - const commandDone$ = log$.cli.filter((log) => log.message === 'command_done') - - // Reporting is done every `throttleProgress` milliseconds - // and once all packages are fetched. - const sampler = opts.isRecursive - ? most.merge(most.periodic(opts.throttleProgress).until(commandDone$), commandDone$) - : most.merge( - most.periodic(opts.throttleProgress).since(resolutionStarted$).until(most.merge<{}>(importingDone$.skip(1), commandDone$)), - importingDone$, - ) - const progress = most.sample( - createStatusMessage, - sampler, - resolvingContentLog$, - fedtchedLog$, - foundInStoreLog$, - importingDone$, - ) - // Avoid logs after all resolved packages were downloaded. - // Fixing issue: https://github.com/pnpm/pnpm/issues/1028#issuecomment-364782901 - .skipAfter((msg) => msg.done === true) - - return most.of(progress) - } - const progress = most.combine( - createStatusMessage, - resolvingContentLog$, - fedtchedLog$, - foundInStoreLog$, - opts.isRecursive ? most.of(false) : importingDone$, - ) - return most.of(progress) + return output$.map((msg: any) => { // tslint:disable-line:no-any + msg['msg'] = zoomOut(opts.cwd, requirer, msg['msg']) + return msg + }) + }) +} + +function throttledProgressOutput ( + throttleProgress: number, + importingDone$: most.Stream, + progress$: most.Stream, +) { + // Reporting is done every `throttleProgress` milliseconds + // and once all packages are fetched. + const sampler = most.merge( + most.periodic(throttleProgress).until(importingDone$.skip(1)), + importingDone$, + ) + return most.sample( + createStatusMessage, + sampler, + progress$, + importingDone$, + ) + // Avoid logs after all resolved packages were downloaded. + // Fixing issue: https://github.com/pnpm/pnpm/issues/1028#issuecomment-364782901 + .skipAfter((msg) => msg['done'] === true) +} + +function nonThrottledProgressOutput ( + importingDone$: most.Stream, + progress$: most.Stream, +) { + return most.combine( + createStatusMessage, + progress$, + importingDone$, + ) +} + +function getModulesInstallProgress$ ( + stage$: most.Stream, + progress$: most.Stream, +) { + const modulesInstallProgressPushStream = new PushStream() + const progessStatsPushStreamByRequirer = getProgessStatsPushStreamByRequirer(progress$) + + const stagePushStreamByRequirer: { + [requirer: string]: PushStream, + } = {} + stage$ + .forEach((log: StageLog) => { + if (!stagePushStreamByRequirer[log.prefix]) { + stagePushStreamByRequirer[log.prefix] = new PushStream() + if (!progessStatsPushStreamByRequirer[log.prefix]) { + progessStatsPushStreamByRequirer[log.prefix] = new PushStream() + } + modulesInstallProgressPushStream.next({ + importingDone$: stage$ToImportingDone$(most.from(stagePushStreamByRequirer[log.prefix].observable)), + progress$: most.from(progessStatsPushStreamByRequirer[log.prefix].observable), + requirer: log.prefix, + }) + } + stagePushStreamByRequirer[log.prefix].next(log) + if (log.stage === 'importing_done') { + progessStatsPushStreamByRequirer[log.prefix].complete() + stagePushStreamByRequirer[log.prefix].complete() + } + }) + + return most.from(modulesInstallProgressPushStream.observable) +} + +function stage$ToImportingDone$ (stage$: most.Stream) { + return stage$ + .filter((log: StageLog) => log.stage === 'importing_done') + .constant(true) + .take(1) + .startWith(false) + .multicast() +} + +function getProgessStatsPushStreamByRequirer (progress$: most.Stream) { + const progessStatsPushStreamByRequirer: { + [requirer: string]: PushStream, + } = {} + + const previousProgressStatsByRequirer: { [requirer: string]: ProgressStats } = {} + progress$ + .forEach((log: ProgressLog) => { + previousProgressStatsByRequirer[log.requester] = { + fetched: 0, + resolved: 0, + reused: 0, + ...previousProgressStatsByRequirer[log.requester], + } + switch (log.status) { + case 'resolved': + previousProgressStatsByRequirer[log.requester].resolved++ + break + case 'fetched': + previousProgressStatsByRequirer[log.requester].fetched++ + break + case 'found_in_store': + previousProgressStatsByRequirer[log.requester].reused++ + break + } + if (!progessStatsPushStreamByRequirer[log.requester]) { + progessStatsPushStreamByRequirer[log.requester] = new PushStream() + } + progessStatsPushStreamByRequirer[log.requester].next(previousProgressStatsByRequirer[log.requester]) + }) + + return progessStatsPushStreamByRequirer +} + +function createStatusMessage ( + progress: ProgressStats, + importingDone: boolean, +) { + const msg = `Resolving: total ${hlValue(progress.resolved.toString())}, reused ${hlValue(progress.reused.toString())}, downloaded ${hlValue(progress.fetched.toString())}` + if (importingDone) { + return { + done: true, + fixed: false, + msg: `${msg}, done`, + } + } + return { + fixed: true, + msg, + } } diff --git a/packages/default-reporter/src/reporterForServer.ts b/packages/default-reporter/src/reporterForServer.ts index 2c53aa77d2..c859162ff4 100644 --- a/packages/default-reporter/src/reporterForServer.ts +++ b/packages/default-reporter/src/reporterForServer.ts @@ -10,12 +10,8 @@ export default function ( complete: () => undefined, error: () => undefined, next (log) { - if (log.name === 'pnpm:progress') { - switch (log.status) { - case 'fetched': - case 'fetching_started': - console.log(`${chalk.cyan(log.status)} ${log.pkgId}`) - } + if (log.name === 'pnpm:fetching-progress') { + console.log(`${chalk.cyan(`fetching_${log.status}`)} ${log.packageId}`) return } switch (log.level) { diff --git a/packages/default-reporter/test/index.ts b/packages/default-reporter/test/index.ts index 5b98eb4aa6..fa4e347e4f 100644 --- a/packages/default-reporter/test/index.ts +++ b/packages/default-reporter/test/index.ts @@ -4,10 +4,8 @@ import { deprecationLogger, hookLogger, packageJsonLogger, - progressLogger, rootLogger, skippedOptionalDependencyLogger, - stageLogger, statsLogger, summaryLogger, } from '@pnpm/core-loggers' @@ -17,15 +15,14 @@ import logger, { } from '@pnpm/logger' import chalk from 'chalk' import { stripIndent, stripIndents } from 'common-tags' -import delay from 'delay' import loadJsonFile from 'load-json-file' -import most = require('most') import normalizeNewline = require('normalize-newline') import path = require('path') import R = require('ramda') import StackTracey = require('stacktracey') import test = require('tape') import './reportingLifecycleScripts' +import './reportingProgress' import './reportingScope' const WARN = chalk.bgYellow.black('\u2009WARN\u2009') @@ -35,178 +32,9 @@ const versionColor = chalk.grey const ADD = chalk.green('+') const SUB = chalk.red('-') const h1 = chalk.cyanBright -const hlValue = chalk.cyanBright -const hlPkgId = chalk['whiteBright'] const EOL = '\n' -test('prints progress beginning', t => { - const output$ = toOutput$({ - context: { - argv: ['install'], - }, - streamParser: createStreamParser(), - }) - - const pkgId = 'registry.npmjs.org/foo/1.0.0' - - progressLogger.debug({ - pkgId, - status: 'resolving_content', - }) - - t.plan(1) - - output$.take(1).subscribe({ - complete: () => t.end(), - error: t.end, - next: output => { - t.equal(output, `Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}`) - }, - }) -}) - -test('prints progress beginning when appendOnly is true', t => { - const output$ = toOutput$({ - context: { argv: ['install'] }, - reportingOptions: { - appendOnly: true, - }, - streamParser: createStreamParser(), - }) - - const pkgId = 'registry.npmjs.org/foo/1.0.0' - - progressLogger.debug({ - pkgId, - status: 'resolving_content', - }) - - t.plan(1) - - output$.take(1).subscribe({ - complete: () => t.end(), - error: t.end, - next: output => { - t.equal(output, `Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}`) - }, - }) -}) - -test('prints progress beginning during recursive install', t => { - const output$ = toOutput$({ - context: { argv: ['recursive'] }, - streamParser: createStreamParser(), - }) - - const pkgId = 'registry.npmjs.org/foo/1.0.0' - - progressLogger.debug({ - pkgId, - status: 'resolving_content', - }) - - t.plan(1) - - output$.take(1).subscribe({ - complete: () => t.end(), - error: t.end, - next: output => { - t.equal(output, `Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}`) - }, - }) -}) - -test('prints progress on first download', t => { - const output$ = toOutput$({ - context: { argv: ['install'] }, - reportingOptions: { throttleProgress: 0 }, - streamParser: createStreamParser(), - }) - - const pkgId = 'registry.npmjs.org/foo/1.0.0' - - progressLogger.debug({ - pkgId, - status: 'resolving_content', - }) - progressLogger.debug({ - pkgId, - status: 'fetched', - }) - - t.plan(1) - - output$.skip(1).take(1).subscribe({ - complete: () => t.end(), - error: t.end, - next: output => { - t.equal(output, `Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('1')}`) - }, - }) -}) - -test('moves fixed line to the end', async t => { - const prefix = process.cwd() - const output$ = toOutput$({ - context: { argv: ['install'] }, - reportingOptions: { throttleProgress: 0 }, - streamParser: createStreamParser(), - }) - - output$.skip(3).take(1).map(normalizeNewline).subscribe({ - complete: v => t.end(), - error: t.end, - next: output => { - t.equal(output, `${WARN} foo` + EOL + - `Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('1')}, done`) - }, - }) - - const pkgId = 'registry.npmjs.org/foo/1.0.0' - - progressLogger.debug({ - pkgId, - status: 'resolving_content', - }) - progressLogger.debug({ - pkgId, - status: 'fetched', - }) - logger.warn({ message: 'foo', prefix }) - - await delay(0) // w/o delay warning goes below for some reason. Started to happen after switch to most - - stageLogger.debug('resolution_done') - stageLogger.debug('importing_done') - - t.plan(1) -}) - -test('prints "Already up-to-date"', t => { - const output$ = toOutput$({ - context: { argv: ['install'] }, - streamParser: createStreamParser(), - }) - - const prefix = process.cwd() - - statsLogger.debug({ added: 0, prefix }) - statsLogger.debug({ removed: 0, prefix }) - - t.plan(1) - - output$.take(1).map(normalizeNewline).subscribe({ - complete: () => t.end(), - error: t.end, - next: output => { - t.equal(output, stripIndents` - Already up-to-date - `) - }, - }) -}) - test('prints summary (of current package only)', t => { const prefix = '/home/jane/project' const output$ = toOutput$({ @@ -708,150 +536,6 @@ test('prints info', t => { }) }) -test('prints progress of big files download', async t => { - t.plan(6) - - let output$ = toOutput$({ - context: { argv: ['install'] }, - reportingOptions: { throttleProgress: 0 }, - streamParser: createStreamParser(), - }) - .map(normalizeNewline) as most.Stream - const stream$: most.Stream[] = [] - - const pkgId1 = 'registry.npmjs.org/foo/1.0.0' - const pkgId2 = 'registry.npmjs.org/bar/2.0.0' - const pkgId3 = 'registry.npmjs.org/qar/3.0.0' - - stream$.push( - output$.take(1) - .tap(output => t.equal(output, `Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}`)) - ) - - output$ = output$.skip(1) - - stream$.push( - output$.take(1) - .tap(output => t.equal(output, stripIndents` - Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')} - Downloading ${hlPkgId(pkgId1)}: ${hlValue('0 B')}/${hlValue('10.5 MB')} - `)) - ) - - output$ = output$.skip(1) - - stream$.push( - output$.take(1) - .tap(output => t.equal(output, stripIndents` - Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')} - Downloading ${hlPkgId(pkgId1)}: ${hlValue('5.77 MB')}/${hlValue('10.5 MB')} - `)) - ) - - output$ = output$.skip(2) - - stream$.push( - output$.take(1) - .tap(output => t.equal(output, stripIndents` - Resolving: total ${hlValue('2')}, reused ${hlValue('0')}, downloaded ${hlValue('0')} - Downloading ${hlPkgId(pkgId1)}: ${hlValue('7.34 MB')}/${hlValue('10.5 MB')} - `, 'downloading of small package not reported')) - ) - - output$ = output$.skip(3) - - stream$.push( - output$.take(1) - .tap(output => t.equal(output, stripIndents` - Resolving: total ${hlValue('3')}, reused ${hlValue('0')}, downloaded ${hlValue('0')} - Downloading ${hlPkgId(pkgId1)}: ${hlValue('7.34 MB')}/${hlValue('10.5 MB')} - Downloading ${hlPkgId(pkgId3)}: ${hlValue('19.9 MB')}/${hlValue('21 MB')} - `)) - ) - - output$ = output$.skip(1) - - stream$.push( - output$.take(1) - .tap(output => t.equal(output, stripIndents` - Downloading ${hlPkgId(pkgId1)}: ${hlValue('10.5 MB')}/${hlValue('10.5 MB')}, done - Resolving: total ${hlValue('3')}, reused ${hlValue('0')}, downloaded ${hlValue('0')} - Downloading ${hlPkgId(pkgId3)}: ${hlValue('19.9 MB')}/${hlValue('21 MB')} - `)) - ) - - most.mergeArray(stream$) - .subscribe({ - complete: () => t.end(), - error: t.end, - next: () => undefined, - }) - - progressLogger.debug({ - pkgId: pkgId1, - status: 'resolving_content', - }) - - progressLogger.debug({ - attempt: 1, - pkgId: pkgId1, - size: 1024 * 1024 * 10, // 10 MB - status: 'fetching_started', - }) - - await delay(0) - - progressLogger.debug({ - downloaded: 1024 * 1024 * 5.5, // 5.5 MB - pkgId: pkgId1, - status: 'fetching_progress', - }) - - progressLogger.debug({ - pkgId: pkgId2, - status: 'resolving_content', - }) - - progressLogger.debug({ - attempt: 1, - pkgId: pkgId1, - size: 10, // 10 B - status: 'fetching_started', - }) - - progressLogger.debug({ - downloaded: 1024 * 1024 * 7, - pkgId: pkgId1, - status: 'fetching_progress', - }) - - progressLogger.debug({ - pkgId: pkgId3, - status: 'resolving_content', - }) - - progressLogger.debug({ - attempt: 1, - pkgId: pkgId3, - size: 1024 * 1024 * 20, // 20 MB - status: 'fetching_started', - }) - - await delay(0) - - progressLogger.debug({ - downloaded: 1024 * 1024 * 19, // 19 MB - pkgId: pkgId3, - status: 'fetching_progress', - }) - - progressLogger.debug({ - downloaded: 1024 * 1024 * 10, // 10 MB - pkgId: pkgId1, - status: 'fetching_progress', - }) -}) - test('prints added/removed stats during installation', t => { const output$ = toOutput$({ context: { argv: ['install'] }, diff --git a/packages/default-reporter/test/reportingProgress.ts b/packages/default-reporter/test/reportingProgress.ts new file mode 100644 index 0000000000..8ff7afa704 --- /dev/null +++ b/packages/default-reporter/test/reportingProgress.ts @@ -0,0 +1,425 @@ +import { PnpmConfigs } from '@pnpm/config' +import { + fetchingProgressLogger, + progressLogger, + stageLogger, + statsLogger, +} from '@pnpm/core-loggers' +import { toOutput$ } from '@pnpm/default-reporter' +import logger, { + createStreamParser, +} from '@pnpm/logger' +import chalk from 'chalk' +import { stripIndents } from 'common-tags' +import delay from 'delay' +import most = require('most') +import normalizeNewline = require('normalize-newline') +import test = require('tape') + +const WARN = chalk.bgYellow.black('\u2009WARN\u2009') +const hlValue = chalk.cyanBright +const hlPkgId = chalk['whiteBright'] + +const EOL = '\n' + +test('prints progress beginning', t => { + const output$ = toOutput$({ + context: { + argv: ['install'], + configs: { prefix: '/src/project' } as PnpmConfigs, + }, + streamParser: createStreamParser(), + }) + + stageLogger.debug({ + prefix: '/src/project', + stage: 'resolution_started', + }) + progressLogger.debug({ + packageId: 'registry.npmjs.org/foo/1.0.0', + requester: '/src/project', + status: 'resolved', + }) + + t.plan(1) + + output$.take(1).subscribe({ + complete: () => t.end(), + error: t.end, + next: output => { + t.equal(output, `Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}`) + }, + }) +}) + +test('prints progress beginning of node_modules from not cwd', t => { + const output$ = toOutput$({ + context: { + argv: ['install'], + configs: { prefix: '/src/projects' } as PnpmConfigs, + }, + streamParser: createStreamParser(), + }) + + stageLogger.debug({ + prefix: '/src/projects/foo', + stage: 'resolution_started', + }) + progressLogger.debug({ + packageId: 'registry.npmjs.org/foo/1.0.0', + requester: '/src/projects/foo', + status: 'resolved', + }) + + t.plan(1) + + output$.take(1).subscribe({ + complete: () => t.end(), + error: t.end, + next: output => { + t.equal(output, `foo | Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}`) + }, + }) +}) + +test('prints progress beginning when appendOnly is true', t => { + const output$ = toOutput$({ + context: { + argv: ['install'], + configs: { prefix: '/src/project' } as PnpmConfigs, + }, + reportingOptions: { + appendOnly: true, + }, + streamParser: createStreamParser(), + }) + + stageLogger.debug({ + prefix: '/src/project', + stage: 'resolution_started', + }) + progressLogger.debug({ + packageId: 'registry.npmjs.org/foo/1.0.0', + requester: '/src/project', + status: 'resolved', + }) + + t.plan(1) + + output$.take(1).subscribe({ + complete: () => t.end(), + error: t.end, + next: output => { + t.equal(output, `Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}`) + }, + }) +}) + +test('prints progress beginning during recursive install', t => { + const output$ = toOutput$({ + context: { + argv: ['recursive'], + configs: { prefix: '/src/project' } as PnpmConfigs, + }, + streamParser: createStreamParser(), + }) + + stageLogger.debug({ + prefix: '/src/project', + stage: 'resolution_started', + }) + progressLogger.debug({ + packageId: 'registry.npmjs.org/foo/1.0.0', + requester: '/src/project', + status: 'resolved', + }) + + t.plan(1) + + output$.take(1).subscribe({ + complete: () => t.end(), + error: t.end, + next: output => { + t.equal(output, `Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}`) + }, + }) +}) + +test('prints progress on first download', async t => { + t.plan(1) + + const output$ = toOutput$({ + context: { + argv: ['install'], + configs: { prefix: '/src/project' } as PnpmConfigs, + }, + reportingOptions: { throttleProgress: 0 }, + streamParser: createStreamParser(), + }) + + output$.skip(1).take(1).subscribe({ + complete: () => t.end(), + error: t.end, + next: output => { + t.equal(output, `Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('1')}`) + }, + }) + + const packageId = 'registry.npmjs.org/foo/1.0.0' + + stageLogger.debug({ + prefix: '/src/project', + stage: 'resolution_started', + }) + progressLogger.debug({ + packageId, + requester: '/src/project', + status: 'resolved', + }) + + await delay(0) + + progressLogger.debug({ + packageId, + requester: '/src/project', + status: 'fetched', + }) +}) + +test('moves fixed line to the end', async t => { + const prefix = '/src/project' + const output$ = toOutput$({ + context: { + argv: ['install'], + configs: { prefix } as PnpmConfigs, + }, + reportingOptions: { throttleProgress: 0 }, + streamParser: createStreamParser(), + }) + + output$.skip(3).take(1).map(normalizeNewline).subscribe({ + complete: () => t.end(), + error: t.end, + next: output => { + t.equal(output, `${WARN} foo` + EOL + + `Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('1')}, done`) + }, + }) + + const packageId = 'registry.npmjs.org/foo/1.0.0' + + stageLogger.debug({ + prefix, + stage: 'resolution_started', + }) + progressLogger.debug({ + packageId, + requester: prefix, + status: 'resolved', + }) + + await delay(0) + + progressLogger.debug({ + packageId, + requester: prefix, + status: 'fetched', + }) + logger.warn({ message: 'foo', prefix }) + + await delay(10) // w/o delay warning goes below for some reason. Started to happen after switch to most + + stageLogger.debug({ + prefix: prefix, + stage: 'resolution_done', + }) + stageLogger.debug({ + prefix: prefix, + stage: 'importing_done', + }) + + t.plan(1) +}) + +test('prints "Already up-to-date"', t => { + const output$ = toOutput$({ + context: { argv: ['install'] }, + streamParser: createStreamParser(), + }) + + const prefix = process.cwd() + + statsLogger.debug({ added: 0, prefix }) + statsLogger.debug({ removed: 0, prefix }) + + t.plan(1) + + output$.take(1).map(normalizeNewline).subscribe({ + complete: () => t.end(), + error: t.end, + next: output => { + t.equal(output, stripIndents` + Already up-to-date + `) + }, + }) +}) + +test('prints progress of big files download', async t => { + t.plan(6) + + let output$ = toOutput$({ + context: { + argv: ['install'], + configs: { prefix: '/src/project' } as PnpmConfigs, + }, + reportingOptions: { throttleProgress: 0 }, + streamParser: createStreamParser(), + }) + .map(normalizeNewline) as most.Stream + const stream$: most.Stream[] = [] + + const pkgId1 = 'registry.npmjs.org/foo/1.0.0' + const pkgId2 = 'registry.npmjs.org/bar/2.0.0' + const pkgId3 = 'registry.npmjs.org/qar/3.0.0' + + stream$.push( + output$.take(1) + .tap(output => t.equal(output, `Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}`)) + ) + + output$ = output$.skip(1) + + stream$.push( + output$.take(1) + .tap(output => t.equal(output, stripIndents` + Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')} + Downloading ${hlPkgId(pkgId1)}: ${hlValue('0 B')}/${hlValue('10.5 MB')} + `)) + ) + + output$ = output$.skip(1) + + stream$.push( + output$.take(1) + .tap(output => t.equal(output, stripIndents` + Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')} + Downloading ${hlPkgId(pkgId1)}: ${hlValue('5.77 MB')}/${hlValue('10.5 MB')} + `)) + ) + + output$ = output$.skip(2) + + stream$.push( + output$.take(1) + .tap(output => t.equal(output, stripIndents` + Resolving: total ${hlValue('2')}, reused ${hlValue('0')}, downloaded ${hlValue('0')} + Downloading ${hlPkgId(pkgId1)}: ${hlValue('7.34 MB')}/${hlValue('10.5 MB')} + `, 'downloading of small package not reported')) + ) + + output$ = output$.skip(3) + + stream$.push( + output$.take(1) + .tap(output => t.equal(output, stripIndents` + Resolving: total ${hlValue('3')}, reused ${hlValue('0')}, downloaded ${hlValue('0')} + Downloading ${hlPkgId(pkgId1)}: ${hlValue('7.34 MB')}/${hlValue('10.5 MB')} + Downloading ${hlPkgId(pkgId3)}: ${hlValue('19.9 MB')}/${hlValue('21 MB')} + `)) + ) + + output$ = output$.skip(1) + + stream$.push( + output$.take(1) + .tap(output => t.equal(output, stripIndents` + Downloading ${hlPkgId(pkgId1)}: ${hlValue('10.5 MB')}/${hlValue('10.5 MB')}, done + Resolving: total ${hlValue('3')}, reused ${hlValue('0')}, downloaded ${hlValue('0')} + Downloading ${hlPkgId(pkgId3)}: ${hlValue('19.9 MB')}/${hlValue('21 MB')} + `)) + ) + + most.mergeArray(stream$) + .subscribe({ + complete: () => t.end(), + error: t.end, + next: () => undefined, + }) + + stageLogger.debug({ + prefix: '/src/project', + stage: 'resolution_started', + }) + + progressLogger.debug({ + packageId: pkgId1, + requester: '/src/project', + status: 'resolved', + }) + + await delay(10) + + fetchingProgressLogger.debug({ + attempt: 1, + packageId: pkgId1, + size: 1024 * 1024 * 10, // 10 MB + status: 'started', + }) + + await delay(10) + + fetchingProgressLogger.debug({ + downloaded: 1024 * 1024 * 5.5, // 5.5 MB + packageId: pkgId1, + status: 'in_progress', + }) + + progressLogger.debug({ + packageId: pkgId2, + requester: '/src/project', + status: 'resolved', + }) + + await delay(10) + + fetchingProgressLogger.debug({ + attempt: 1, + packageId: pkgId1, + size: 10, // 10 B + status: 'started', + }) + + fetchingProgressLogger.debug({ + downloaded: 1024 * 1024 * 7, + packageId: pkgId1, + status: 'in_progress', + }) + + progressLogger.debug({ + packageId: pkgId3, + requester: '/src/project', + status: 'resolved', + }) + + fetchingProgressLogger.debug({ + attempt: 1, + packageId: pkgId3, + size: 1024 * 1024 * 20, // 20 MB + status: 'started', + }) + + await delay(10) + + fetchingProgressLogger.debug({ + downloaded: 1024 * 1024 * 19, // 19 MB + packageId: pkgId3, + status: 'in_progress', + }) + + fetchingProgressLogger.debug({ + downloaded: 1024 * 1024 * 10, // 10 MB + packageId: pkgId1, + status: 'in_progress', + }) +}) diff --git a/packages/headless/src/index.ts b/packages/headless/src/index.ts index e09f16eb83..acd4334028 100644 --- a/packages/headless/src/index.ts +++ b/packages/headless/src/index.ts @@ -161,7 +161,11 @@ export default async (opts: HeadlessOptions) => { }) } - stageLogger.debug('importing_started') + stageLogger.debug({ + prefix: opts.shrinkwrapDirectory, + stage: 'importing_started', + }) + const filteredShrinkwrap = filterShrinkwrapByImporters(wantedShrinkwrap, opts.importers.map((importer) => importer.id), { ...filterOpts, failOnMissingDependencies: true, @@ -188,7 +192,11 @@ export default async (opts: HeadlessOptions) => { linkAllModules(depGraph, { optional: opts.include.optionalDependencies }), linkAllPkgs(opts.storeController, R.values(depGraph), opts), ]) - stageLogger.debug('importing_done') + + stageLogger.debug({ + prefix: opts.shrinkwrapDirectory, + stage: 'importing_done', + }) function warn (message: string) { logger.warn({ @@ -409,6 +417,7 @@ interface ShrinkwrapToDepGraphOptions { force: boolean, independentLeaves: boolean, importerIds: string[], + shrinkwrapDirectory: string, storeController: StoreController, store: string, prefix: string, @@ -438,14 +447,15 @@ async function shrinkwrapToDepGraph ( const resolution = pkgSnapshotToResolution(relDepPath, pkgSnapshot, opts.defaultRegistry) // TODO: optimize. This info can be already returned by pkgSnapshotToResolution() const pkgName = nameVerFromPkgSnapshot(relDepPath, pkgSnapshot).name - const pkgId = pkgSnapshot.id || depPath + const packageId = pkgSnapshot.id || depPath progressLogger.debug({ - pkgId, - status: 'resolving_content', + packageId, + requester: opts.shrinkwrapDirectory, + status: 'resolved', }) let fetchResponse = opts.storeController.fetchPackage({ force: false, - pkgId, + pkgId: packageId, prefix: opts.prefix, resolution, verifyStoreIntegrity: opts.verifyStoreIntegrity, @@ -454,12 +464,13 @@ async function shrinkwrapToDepGraph ( fetchResponse.fetchingFiles // tslint:disable-line .then((fetchResult) => { progressLogger.debug({ - pkgId, + packageId, + requester: opts.shrinkwrapDirectory, status: fetchResult.fromStore ? 'found_in_store' : 'fetched', }) }) - const pkgLocation = await opts.storeController.getPackageLocation(pkgId, pkgName, { + const pkgLocation = await opts.storeController.getPackageLocation(packageId, pkgName, { importerPrefix: opts.prefix, targetEngine: opts.sideEffectsCacheRead && !opts.force && ENGINE_NAME || undefined, }) @@ -484,7 +495,7 @@ async function shrinkwrapToDepGraph ( optional: !!pkgSnapshot.optional, optionalDependencies: new Set(R.keys(pkgSnapshot.optionalDependencies)), peripheralLocation, - pkgId, + pkgId: packageId, prepare: pkgSnapshot.prepare === true, relDepPath: depPath, requiresBuild: pkgSnapshot.requiresBuild === true, diff --git a/packages/headless/test/index.ts b/packages/headless/test/index.ts index 0742221397..ee8c65e06d 100644 --- a/packages/headless/test/index.ts +++ b/packages/headless/test/index.ts @@ -63,13 +63,15 @@ test('installing a simple project', async (t) => { } as StatsLog), 'removed stat') t.ok(reporter.calledWithMatch({ level: 'debug', - message: 'importing_done', name: 'pnpm:stage', + prefix, + stage: 'importing_done', } as StageLog), 'importing stage done logged') t.ok(reporter.calledWithMatch({ level: 'debug', - pkgId: 'localhost+4873/is-negative/2.1.0', - status: 'resolving_content', + packageId: 'localhost+4873/is-negative/2.1.0', + requester: prefix, + status: 'resolved', }), 'logs that package is being resolved') t.end() @@ -356,13 +358,15 @@ test('available packages are used when node_modules is not clean', async (t) => t.notOk(reporter.calledWithMatch({ level: 'debug', - pkgId: 'localhost+4873/balanced-match/1.0.0', - status: 'resolving_content', + packageId: 'localhost+4873/balanced-match/1.0.0', + requester: projectDir, + status: 'resolved', }), 'does not resolve already available package') t.ok(reporter.calledWithMatch({ level: 'debug', - pkgId: 'localhost+4873/rimraf/2.6.2', - status: 'resolving_content', + packageId: 'localhost+4873/rimraf/2.6.2', + requester: projectDir, + status: 'resolved', }), 'resolves rimraf') t.end() @@ -394,13 +398,15 @@ test('available packages are relinked during forced install', async (t) => { t.ok(reporter.calledWithMatch({ level: 'debug', - pkgId: 'localhost+4873/balanced-match/1.0.0', - status: 'resolving_content', + packageId: 'localhost+4873/balanced-match/1.0.0', + requester: projectDir, + status: 'resolved', }), 'does not resolve already available package') t.ok(reporter.calledWithMatch({ level: 'debug', - pkgId: 'localhost+4873/rimraf/2.6.2', - status: 'resolving_content', + packageId: 'localhost+4873/rimraf/2.6.2', + requester: projectDir, + status: 'resolved', }), 'resolves rimraf') t.end() @@ -525,8 +531,9 @@ test('independent-leaves: installing a simple project', async (t) => { } as StatsLog), 'removed stat') t.ok(reporter.calledWithMatch({ level: 'debug', - message: 'importing_done', name: 'pnpm:stage', + prefix, + stage: 'importing_done', } as StageLog), 'importing stage done logged') t.end() @@ -572,13 +579,15 @@ test('installing with shamefullyFlatten = true', async (t) => { } as StatsLog), 'removed stat') t.ok(reporter.calledWithMatch({ level: 'debug', - message: 'importing_done', name: 'pnpm:stage', + prefix, + stage: 'importing_done', } as StageLog), 'importing stage done logged') t.ok(reporter.calledWithMatch({ level: 'debug', - pkgId: 'localhost+4873/is-negative/2.1.0', - status: 'resolving_content', + packageId: 'localhost+4873/is-negative/2.1.0', + requester: prefix, + status: 'resolved', }), 'logs that package is being resolved') const modules = await project.loadModules() diff --git a/packages/package-requester/src/packageRequester.ts b/packages/package-requester/src/packageRequester.ts index f4ba8714ba..dc6bea06f6 100644 --- a/packages/package-requester/src/packageRequester.ts +++ b/packages/package-requester/src/packageRequester.ts @@ -1,11 +1,11 @@ import checkPackage from '@pnpm/check-package' -import { progressLogger } from '@pnpm/core-loggers' +import { fetchingProgressLogger } from '@pnpm/core-loggers' import { FetchFunction, FetchOptions, FetchResult, } from '@pnpm/fetcher-base' -import { storeLogger } from '@pnpm/logger' +import pnpmLogger, { storeLogger } from '@pnpm/logger' import pkgIdToFilename from '@pnpm/pkgid-to-filename' import { fromDir as readPkgFromDir } from '@pnpm/read-package-json' import { @@ -37,6 +37,7 @@ import rimraf = require('rimraf-then') import symlinkDir = require('symlink-dir') import writeJsonFile from 'write-json-file' +const dependencyResolvedLogger = pnpmLogger('_dependency_resolved') const TARBALL_INTEGRITY_FILENAME = 'tarball-integrity' export default function ( @@ -164,7 +165,10 @@ async function resolveAndFetch ( const id = pkgId as string - progressLogger.debug({ status: 'resolved', pkgId: id, pkg: options.loggedPkg }) + dependencyResolvedLogger.debug({ + resolution: id, + wanted: options.loggedPkg, + }) if (resolution.type === 'directory') { if (!pkg) { @@ -231,7 +235,6 @@ async function resolveAndFetch ( finishing: fetchResult.finishing, } as PackageResponse } catch (err) { - progressLogger.debug({ status: 'error', pkg: options.loggedPkg }) throw err } } @@ -408,10 +411,19 @@ function fetchToStore ( const fetchedPackage = await ctx.requestsQueue.add(() => ctx.fetch(opts.resolution, target, { cachedTarballLocation: path.join(ctx.storePath, opts.pkgId, 'packed.tgz'), onProgress: (downloaded) => { - progressLogger.debug({ status: 'fetching_progress', pkgId: opts.pkgId, downloaded }) + fetchingProgressLogger.debug({ + downloaded, + packageId: opts.pkgId, + status: 'in_progress', + }) }, onStart: (size, attempt) => { - progressLogger.debug({ status: 'fetching_started', pkgId: opts.pkgId, size, attempt }) + fetchingProgressLogger.debug({ + attempt, + packageId: opts.pkgId, + size, + status: 'started', + }) }, pkgId: opts.pkgId, prefix: opts.prefix, diff --git a/packages/pnpm/src/cmd/recursive/index.ts b/packages/pnpm/src/cmd/recursive/index.ts index 3f28ed6788..a0582bec18 100644 --- a/packages/pnpm/src/cmd/recursive/index.ts +++ b/packages/pnpm/src/cmd/recursive/index.ts @@ -315,8 +315,6 @@ export async function recursive ( }), )) - stageLogger.debug('recursive_importing_done') - await saveState() } diff --git a/packages/pnpm/src/main.ts b/packages/pnpm/src/main.ts index 5b4f019418..644d4c1816 100644 --- a/packages/pnpm/src/main.ts +++ b/packages/pnpm/src/main.ts @@ -16,7 +16,6 @@ import { PnpmConfigs, types, } from '@pnpm/config' -import { cliLogger } from '@pnpm/core-loggers' import logger from '@pnpm/logger' import isCI = require('is-ci') import nopt = require('nopt') @@ -244,6 +243,4 @@ export default async function run (argv: string[]) { } }, 0) }) - - cliLogger.debug('command_done') } diff --git a/packages/resolve-dependencies/src/index.ts b/packages/resolve-dependencies/src/index.ts index 5f63563768..38c305bb6f 100644 --- a/packages/resolve-dependencies/src/index.ts +++ b/packages/resolve-dependencies/src/index.ts @@ -43,6 +43,7 @@ export default async function ( registries: Registries, pnpmVersion: string, sideEffectsCache: boolean, + shrinkwrapDirectory: string, // needed only for logging preferredVersions?: { [packageName: string]: { selector: string, @@ -77,6 +78,7 @@ export default async function ( pnpmVersion: opts.pnpmVersion, registries: opts.registries, resolvedPackagesByPackageId: {} as ResolvedPackagesByPackageId, + shrinkwrapDirectory: opts.shrinkwrapDirectory, skipped: opts.skipped, storeController: opts.storeController, updateDepth: typeof opts.updateDepth === 'number' ? opts.updateDepth : -1, diff --git a/packages/resolve-dependencies/src/resolveDependencies.ts b/packages/resolve-dependencies/src/resolveDependencies.ts index 77418a2c52..78e4e3caa7 100644 --- a/packages/resolve-dependencies/src/resolveDependencies.ts +++ b/packages/resolve-dependencies/src/resolveDependencies.ts @@ -97,6 +97,7 @@ export interface ResolutionContext { pendingNodes: PendingNode[], wantedShrinkwrap: Shrinkwrap, currentShrinkwrap: Shrinkwrap, + shrinkwrapDirectory: string, storeController: StoreController, // the IDs of packages that are not installable skipped: Set, @@ -370,10 +371,6 @@ async function resolveDependency ( name: wantedDependency.alias, rawSpec: wantedDependency.raw, } - progressLogger.debug({ - pkg: loggedPkg, - status: 'installing', - }) let pkgResponse!: PackageResponse try { @@ -439,11 +436,6 @@ async function resolveDependency ( version: manifest.version, }) } - progressLogger.debug({ - pkgId: pkgResponse.body.id, - pkgVersion: manifest.version, - status: 'downloaded_manifest', - }) return null } @@ -518,12 +510,6 @@ async function resolveDependency ( }) } - progressLogger.debug({ - pkgId: pkgResponse.body.id, - pkgVersion: pkg.version, - status: 'downloaded_manifest', - }) - // using colon as it will never be used inside a package ID const nodeId = createNodeId(options.parentNodeId, pkgResponse.body.id) @@ -546,15 +532,17 @@ async function resolveDependency ( } if (!ctx.resolvedPackagesByPackageId[pkgResponse.body.id]) { progressLogger.debug({ - pkgId: pkgResponse.body.id, - status: 'resolving_content', + packageId: pkgResponse.body.id, + requester: ctx.shrinkwrapDirectory, + status: 'resolved', }) // tslint:disable:no-string-literal if (pkgResponse['fetchingFiles']) { pkgResponse['fetchingFiles'] .then((fetchResult: PackageFilesResponse) => { progressLogger.debug({ - pkgId: pkgResponse.body.id, + packageId: pkgResponse.body.id, + requester: ctx.shrinkwrapDirectory, status: fetchResult.fromStore ? 'found_in_store' : 'fetched', }) diff --git a/packages/supi/src/install/index.ts b/packages/supi/src/install/index.ts index 558809c9ba..9b41cff1d2 100644 --- a/packages/supi/src/install/index.ts +++ b/packages/supi/src/install/index.ts @@ -626,7 +626,11 @@ async function installInContext ( }), ) - stageLogger.debug('resolution_started') + stageLogger.debug({ + prefix: ctx.shrinkwrapDirectory, + stage: 'resolution_started', + }) + const { dependenciesTree, outdatedDependencies, @@ -645,6 +649,7 @@ async function installInContext ( pnpmVersion: opts.packageManager.name === 'pnpm' ? opts.packageManager.version : '', preferredVersions: opts.preferredVersions, registries: opts.registries, + shrinkwrapDirectory: opts.shrinkwrapDirectory, // needed only for logging sideEffectsCache: opts.sideEffectsCacheRead, skipped: ctx.skipped, storeController: opts.storeController, @@ -675,7 +680,11 @@ async function installInContext ( virtualStoreDir: ctx.virtualStoreDir, wantedShrinkwrap: ctx.wantedShrinkwrap, }) - stageLogger.debug('resolution_done') + + stageLogger.debug({ + prefix: ctx.shrinkwrapDirectory, + stage: 'resolution_done', + }) const importersToLink = await Promise.all(importers.map(async (importer) => { const resolvedImporter = resolvedImporters[importer.id] diff --git a/packages/supi/src/install/link.ts b/packages/supi/src/install/link.ts index a3be6446d0..c38b8bcf2c 100644 --- a/packages/supi/src/install/link.ts +++ b/packages/supi/src/install/link.ts @@ -149,7 +149,11 @@ export default async function linkPackages ( virtualStoreDir: opts.virtualStoreDir, }) - stageLogger.debug('importing_started') + stageLogger.debug({ + prefix: opts.shrinkwrapDirectory, + stage: 'importing_started', + }) + const importerIds = importers.map((importer) => importer.id) const newCurrentShrinkwrap = filterShrinkwrapByImporters(newWantedShrinkwrap, importerIds, { ...filterOpts, @@ -172,7 +176,11 @@ export default async function linkPackages ( virtualStoreDir: opts.virtualStoreDir, }, ) - stageLogger.debug('importing_done') + + stageLogger.debug({ + prefix: opts.shrinkwrapDirectory, + stage: 'importing_done', + }) const rootDepsByDepPath = depNodes .filter((depNode) => depNode.depth === 0) diff --git a/packages/supi/test/install/misc.ts b/packages/supi/test/install/misc.ts index a1a40f72b0..640615e531 100644 --- a/packages/supi/test/install/misc.ts +++ b/packages/supi/test/install/misc.ts @@ -94,23 +94,27 @@ test('no dependencies (lodash)', async (t: tape.Test) => { } as PackageJsonLog)).callCount, 1, 'initial package.json logged') t.ok(reporter.calledWithMatch({ level: 'debug', - message: 'resolution_started', name: 'pnpm:stage', + prefix: process.cwd(), + stage: 'resolution_started', } as StageLog), 'resolution stage start logged') t.ok(reporter.calledWithMatch({ level: 'debug', - message: 'resolution_done', name: 'pnpm:stage', + prefix: process.cwd(), + stage: 'resolution_done', } as StageLog), 'resolution stage done logged') t.ok(reporter.calledWithMatch({ level: 'debug', - message: 'importing_started', name: 'pnpm:stage', + prefix: process.cwd(), + stage: 'importing_started', } as StageLog), 'importing stage start logged') t.ok(reporter.calledWithMatch({ level: 'debug', - message: 'importing_done', name: 'pnpm:stage', + prefix: process.cwd(), + stage: 'importing_done', } as StageLog), 'importing stage done logged') // Not logged for now // t.ok(reporter.calledWithMatch({ @@ -780,12 +784,14 @@ test('shrinkwrap locks npm dependencies', async (t: tape.Test) => { t.ok(reporter.calledWithMatch({ level: 'debug', name: 'pnpm:progress', - pkgId: 'localhost+4873/pkg-with-1-dep/100.0.0', - status: 'resolving_content', + packageId: 'localhost+4873/pkg-with-1-dep/100.0.0', + requester: process.cwd(), + status: 'resolved', } as ProgressLog), 'logs that package is being resolved') t.ok(reporter.calledWithMatch({ level: 'debug', - pkgId: 'localhost+4873/pkg-with-1-dep/100.0.0', + packageId: 'localhost+4873/pkg-with-1-dep/100.0.0', + requester: process.cwd(), status: 'fetched', } as ProgressLog), 'logged that package was fetched from registry') @@ -800,12 +806,14 @@ test('shrinkwrap locks npm dependencies', async (t: tape.Test) => { t.ok(reporter.calledWithMatch({ level: 'debug', - pkgId: 'localhost+4873/pkg-with-1-dep/100.0.0', - status: 'resolving_content', + packageId: 'localhost+4873/pkg-with-1-dep/100.0.0', + requester: process.cwd(), + status: 'resolved', } as ProgressLog), 'logs that package is being resolved') t.ok(reporter.calledWithMatch({ level: 'debug', - pkgId: 'localhost+4873/pkg-with-1-dep/100.0.0', + packageId: 'localhost+4873/pkg-with-1-dep/100.0.0', + requester: process.cwd(), status: 'found_in_store', } as ProgressLog), 'logged that package was found in store')