feat(reporting): progress reporting per workspace package

close #1135 PR #1586
2026-03-24 18:11:39 -04:00 · 2019-01-04 01:49:09 +02:00
parent bcc7987aad
commit b9c3a1908c
23 changed files with 746 additions and 532 deletions
--- 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'
--- a/packages/core-loggers/src/cliLogger.ts
+++ b/packages/core-loggers/src/cliLogger.ts
@@ -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'}
--- a/packages/core-loggers/src/fetchingProgressLogger.ts
+++ 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<FetchingProgressMessage> // 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
--- 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
--- 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<ProgressMessage> // 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
--- 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<StageMessage>('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
--- a/packages/default-reporter/src/index.ts
+++ b/packages/default-reporter/src/index.ts
@@ -70,6 +70,7 @@ export function toOutput$ (
  },
 ): most.Stream<string> {
  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<logs.CliLog>(cliPushStream.observable),
    deprecation: most.from<logs.DeprecationLog>(deprecationPushStream.observable),
+    fetchingProgress: most.from<logs.FetchingProgressLog>(fetchingProgressPushStream.observable),
    hook: most.from<logs.HookLog>(hookPushStream.observable),
    installCheck: most.from<logs.InstallCheckLog>(installCheckPushStream.observable),
    lifecycle: most.from<logs.LifecycleLog>(lifecyclePushStream.observable),
--- 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<logs.FetchingProgressLog>,
    progress: most.Stream<logs.ProgressLog>,
    stage: most.Stream<logs.StageLog>,
    deprecation: most.Stream<logs.DeprecationLog>,
@@ -27,7 +28,6 @@ export default function (
    packageJson: most.Stream<logs.PackageJsonLog>,
    link: most.Stream<logs.LinkLog>,
    other: most.Stream<logs.Log>,
-    cli: most.Stream<logs.CliLog>,
    hook: most.Stream<logs.HookLog>,
    scope: most.Stream<logs.ScopeLog>,
    skippedOptionalDependency: most.Stream<logs.SkippedOptionalDependencyLog>,
@@ -46,7 +46,10 @@ export default function (
  const cwd = opts.pnpmConfigs && opts.pnpmConfigs.prefix || process.cwd()

  const outputs: Array<most.Stream<most.Stream<{msg: string}>>> = [
-    reportProgress(log$, opts),
+    reportProgress(log$, {
+      cwd,
+      throttleProgress: opts.throttleProgress,
+    }),
    reportLifecycleScripts(log$, {
      appendOnly: opts.appendOnly,
      cwd,
--- 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<ProgressLog>,
+    fetchingProgress: most.Stream<FetchingProgressLog>,
  },
 ) => {
-  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' : ''}`,
          }
        })
    })
--- 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<boolean>,
+  progress$: most.Stream<ProgressStats>,
+  requirer: string,
+}

 export default (
  log$: {
    progress: most.Stream<ProgressLog>,
-    cli: most.Stream<CliLog>,
    stage: most.Stream<StageLog>,
  },
  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<boolean>,
+  progress$: most.Stream<ProgressStats>,
+) {
+  // 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<boolean>,
+  progress$: most.Stream<ProgressStats>,
+) {
+  return most.combine(
+    createStatusMessage,
+    progress$,
+    importingDone$,
+  )
+}
+
+function getModulesInstallProgress$ (
+  stage$: most.Stream<StageLog>,
+  progress$: most.Stream<ProgressLog>,
+) {
+  const modulesInstallProgressPushStream = new PushStream<ModulesInstallProgress>()
+  const progessStatsPushStreamByRequirer = getProgessStatsPushStreamByRequirer(progress$)
+
+  const stagePushStreamByRequirer: {
+    [requirer: string]: PushStream<StageLog>,
+  } = {}
+  stage$
+    .forEach((log: StageLog) => {
+      if (!stagePushStreamByRequirer[log.prefix]) {
+        stagePushStreamByRequirer[log.prefix] = new PushStream<StageLog>()
+        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<StageLog>) {
+  return stage$
+    .filter((log: StageLog) => log.stage === 'importing_done')
+    .constant(true)
+    .take(1)
+    .startWith(false)
+    .multicast()
+}
+
+function getProgessStatsPushStreamByRequirer (progress$: most.Stream<ProgressLog>) {
+  const progessStatsPushStreamByRequirer: {
+    [requirer: string]: PushStream<ProgressStats>,
+  } = {}
+
+  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<ProgressStats>()
+      }
+      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,
+  }
 }
--- 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) {
--- 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<string>
-  const stream$: most.Stream<string>[] = []
-
-  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'] },
--- a/packages/default-reporter/test/reportingProgress.ts
+++ 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<string>
+  const stream$: most.Stream<string>[] = []
+
+  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',
+  })
+})
--- 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,
--- 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()
--- 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,
--- 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()
  }

--- 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')
 }
--- 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,
--- 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<string>,
@@ -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',
          })
--- 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<ImporterToLink>(importers.map(async (importer) => {
    const resolvedImporter = resolvedImporters[importer.id]
--- 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)
--- 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')