feat(reporter): show the progress of adding pkgs to virtual store

close #2832
PR #2845

.changeset/cuddly-moles-warn.md

@@ -0,0 +1,5 @@
+---
+"pnpm": minor
+---
+
+The progress indicator now also shows the number of dependencies that are being added to the modules direcotory.

.changeset/long-jeans-attack.md

@@ -0,0 +1,5 @@
+---
+"@pnpm/core-loggers": major
+---
+
+Remove `importingLogger`. Importing should be logged by a new type of progress log status: `imported`.

.changeset/nice-lies-shout.md

@@ -0,0 +1,6 @@
+---
+"@pnpm/headless": minor
+"supi": patch
+---
+
+After a package is linked, copied, or cloned to the virtual store, a progress log is logged with the `imported` status.

.changeset/strange-eagles-sin.md

@@ -0,0 +1,5 @@
+---
+"@pnpm/default-reporter": minor
+---
+
+Show the progress of adding packages to the virtual store.

.changeset/tiny-fishes-nail.md

@@ -0,0 +1,7 @@
+---
+"@pnpm/package-store": major
+"@pnpm/server": major
+"@pnpm/store-controller-types": major
+---
+
+The `importPackage` function of the store controller returns the `importMethod` that was used to link the package to the virtual store. If importing was not needed, `importMethod` is `undefined`.

packages/core-loggers/src/all.ts

@@ -2,7 +2,6 @@ export * from './contextLogger'
 export * from './deprecationLogger'
 export * from './fetchingProgressLogger'
 export * from './hookLogger'
-export * from './importingLogger'
 export * from './installCheckLogger'
 export * from './lifecycleLogger'
 export * from './linkLogger'

packages/core-loggers/src/importingLogger.ts

@@ -1,13 +0,0 @@
-import baseLogger, {
-  LogBase,
-} from '@pnpm/logger'
-
-export const importingLogger = baseLogger('importing')
-
-export interface ImportingMessage {
-  from: string
-  method: string
-  to: string
-}
-
-export type ImportingLog = {name: 'pnpm:importing'} & LogBase & ImportingMessage

packages/core-loggers/src/index.ts

@@ -3,7 +3,6 @@ import {
   DeprecationLog,
   FetchingProgressLog,
   HookLog,
-  ImportingLog,
   InstallCheckLog,
   LifecycleLog,
   LinkLog,
@@ -27,7 +26,6 @@ export type Log =
   | DeprecationLog
   | FetchingProgressLog
   | HookLog
-  | ImportingLog
   | InstallCheckLog
   | LifecycleLog
   | LinkLog

packages/core-loggers/src/progressLogger.ts

@@ -5,10 +5,15 @@ import baseLogger, {
 
 export const progressLogger = baseLogger('progress') as Logger<ProgressMessage> // eslint-disable-line
 
-export interface ProgressMessage {
+export type ProgressMessage = {
   packageId: string
   requester: string
   status: 'fetched' | 'found_in_store' | 'resolved'
+} | {
+  status: 'imported'
+  method: string
+  requester: string
+  to: string
 }
 
 export type ProgressLog = {name: 'pnpm:progress'} & LogBase & ProgressMessage

packages/default-reporter/src/index.ts

@@ -154,10 +154,10 @@ export function toOutput$ (
       case 'pnpm:request-retry':
         requestRetryPushStream.next(log)
         break
-        case 'pnpm' as any: // eslint-disable-line
-        case 'pnpm:global' as any: // eslint-disable-line
-        case 'pnpm:store' as any: // eslint-disable-line
-        case 'pnpm:lockfile' as any: // eslint-disable-line
+      case 'pnpm' as any: // eslint-disable-line
+      case 'pnpm:global' as any: // eslint-disable-line
+      case 'pnpm:store' as any: // eslint-disable-line
+      case 'pnpm:lockfile' as any: // eslint-disable-line
         otherPushStream.next(log)
         break
       }

packages/default-reporter/src/reporterForClient/index.ts

@@ -2,6 +2,7 @@ import { Config } from '@pnpm/config'
 import * as logs from '@pnpm/core-loggers'
 import { LogLevel } from '@pnpm/logger'
 import * as Rx from 'rxjs'
+import { throttleTime } from 'rxjs/operators'
 import reportBigTarballsProgress from './reportBigTarballsProgress'
 import reportContext from './reportContext'
 import reportDeprecations from './reportDeprecations'
@@ -52,11 +53,14 @@ export default function (
 ): Array<Rx.Observable<Rx.Observable<{msg: string}>>> {
   const width = opts.width ?? process.stdout.columns ?? 80
   const cwd = opts.pnpmConfig?.dir ?? process.cwd()
+  const throttle = typeof opts.throttleProgress === 'number' && opts.throttleProgress > 0
+    ? throttleTime(opts.throttleProgress)
+    : undefined
 
   const outputs: Array<Rx.Observable<Rx.Observable<{msg: string}>>> = [
     reportProgress(log$, {
       cwd,
-      throttleProgress: opts.throttleProgress,
+      throttle,
     }),
     reportLifecycleScripts(log$, {
       appendOnly: opts.appendOnly === true || opts.streamLifecycleOutput,

packages/default-reporter/src/reporterForClient/reportProgress.ts

@@ -1,11 +1,12 @@
 import { ProgressLog, StageLog } from '@pnpm/core-loggers'
 import * as Rx from 'rxjs'
-import { filter, map, mapTo, sampleTime, takeWhile, startWith, take } from 'rxjs/operators'
+import { filter, map, mapTo, takeWhile, startWith, take } from 'rxjs/operators'
 import { hlValue } from './outputConstants'
 import { zoomOut } from './utils/zooming'
 
 interface ProgressStats {
   fetched: number
+  imported: number
   resolved: number
   reused: number
 }
@@ -23,12 +24,11 @@ export default (
   },
   opts: {
     cwd: string
-    throttleProgress?: number
+    // eslint-disable-next-line @typescript-eslint/no-explicit-any
+    throttle?: Rx.OperatorFunction<any, any>
   }
 ) => {
-  const progressOutput = typeof opts.throttleProgress === 'number' && opts.throttleProgress > 0
-    ? throttledProgressOutput.bind(null, opts.throttleProgress)
-    : nonThrottledProgressOutput
+  const progressOutput = throttledProgressOutput.bind(null, opts.throttle)
 
   return getModulesInstallProgress$(log$.stage, log$.progress).pipe(
     map(({ importingDone$, progress$, requirer }) => {
@@ -48,14 +48,15 @@ export default (
 }
 
 function throttledProgressOutput (
-  throttleProgress: number,
+  // eslint-disable-next-line @typescript-eslint/no-explicit-any
+  throttle: Rx.OperatorFunction<any, any> | undefined,
   importingDone$: Rx.Observable<boolean>,
   progress$: Rx.Observable<ProgressStats>
 ) {
   // Reporting is done every `throttleProgress` milliseconds
   // and once all packages are fetched.
   return Rx.combineLatest(
-    progress$.pipe(sampleTime(throttleProgress)),
+    throttle ? progress$.pipe(throttle) : progress$,
     importingDone$
   )
     .pipe(
@@ -66,17 +67,6 @@ function throttledProgressOutput (
     )
 }
 
-function nonThrottledProgressOutput (
-  importingDone$: Rx.Observable<boolean>,
-  progress$: Rx.Observable<ProgressStats>
-) {
-  return Rx.combineLatest(
-    progress$,
-    importingDone$
-  )
-    .pipe(map(createStatusMessage))
-}
-
 function getModulesInstallProgress$ (
   stage$: Rx.Observable<StageLog>,
   progress$: Rx.Observable<ProgressLog>
@@ -132,6 +122,7 @@ function getProgessStatsPushStreamByRequirer (progress$: Rx.Observable<ProgressL
       if (!previousProgressStatsByRequirer[log.requester]) {
         previousProgressStatsByRequirer[log.requester] = {
           fetched: 0,
+          imported: 0,
           resolved: 0,
           reused: 0,
         }
@@ -146,6 +137,9 @@ function getProgessStatsPushStreamByRequirer (progress$: Rx.Observable<ProgressL
       case 'found_in_store':
         previousProgressStatsByRequirer[log.requester].reused++
         break
+      case 'imported':
+        previousProgressStatsByRequirer[log.requester].imported++
+        break
       }
       if (!progessStatsPushStreamByRequirer[log.requester]) {
         progessStatsPushStreamByRequirer[log.requester] = new Rx.Subject<ProgressStats>()
@@ -158,7 +152,7 @@ function getProgessStatsPushStreamByRequirer (progress$: Rx.Observable<ProgressL
 }
 
 function createStatusMessage ([progress, importingDone]: [ProgressStats, boolean]) {
-  const msg = `Resolving: total ${hlValue(progress.resolved.toString())}, reused ${hlValue(progress.reused.toString())}, downloaded ${hlValue(progress.fetched.toString())}`
+  const msg = `Progress: resolved ${hlValue(progress.resolved.toString())}, reused ${hlValue(progress.reused.toString())}, downloaded ${hlValue(progress.fetched.toString())}, added ${hlValue(progress.imported.toString())}`
   if (importingDone) {
     return {
       done: true,

packages/default-reporter/test/reportingProgress.ts

@@ -45,7 +45,53 @@ test('prints progress beginning', t => {
     complete: () => t.end(),
     error: t.end,
     next: output => {
-      t.equal(output, `Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}`)
+      t.equal(output, `Progress: resolved ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}, added ${hlValue('0')}`)
+    },
+  })
+})
+
+test('prints all progress stats', t => {
+  const output$ = toOutput$({
+    context: {
+      argv: ['install'],
+      config: { dir: '/src/project' } as Config,
+    },
+    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',
+  })
+  progressLogger.debug({
+    packageId: 'registry.npmjs.org/foo/1.0.0',
+    requester: '/src/project',
+    status: 'fetched',
+  })
+  progressLogger.debug({
+    packageId: 'registry.npmjs.org/bar/1.0.0',
+    requester: '/src/project',
+    status: 'found_in_store',
+  })
+  progressLogger.debug({
+    method: 'hardlink',
+    requester: '/src/project',
+    status: 'imported',
+    to: '/node_modules/.pnpm/foo@1.0.0',
+  })
+
+  t.plan(1)
+
+  output$.pipe(skip(3), take(1)).subscribe({
+    complete: () => t.end(),
+    error: t.end,
+    next: output => {
+      t.equal(output, `Progress: resolved ${hlValue('1')}, reused ${hlValue('1')}, downloaded ${hlValue('1')}, added ${hlValue('1')}`)
     },
   })
 })
@@ -75,7 +121,7 @@ test('prints progress beginning of node_modules from not cwd', t => {
     complete: () => t.end(),
     error: t.end,
     next: output => {
-      t.equal(output, `foo                                      | Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}`)
+      t.equal(output, `foo                                      | Progress: resolved ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}, added ${hlValue('0')}`)
     },
   })
 })
@@ -108,7 +154,7 @@ test('prints progress beginning when appendOnly is true', t => {
     complete: () => t.end(),
     error: t.end,
     next: output => {
-      t.equal(output, `Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}`)
+      t.equal(output, `Progress: resolved ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}, added ${hlValue('0')}`)
     },
   })
 })
@@ -141,7 +187,7 @@ test('prints progress beginning during recursive install', t => {
     complete: () => t.end(),
     error: t.end,
     next: output => {
-      t.equal(output, `Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}`)
+      t.equal(output, `Progress: resolved ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}, added ${hlValue('0')}`)
     },
   })
 })
@@ -162,7 +208,7 @@ test('prints progress on first download', async t => {
     complete: () => t.end(),
     error: t.end,
     next: output => {
-      t.equal(output, `Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('1')}`)
+      t.equal(output, `Progress: resolved ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('1')}, added ${hlValue('0')}`)
     },
   })
 
@@ -202,7 +248,7 @@ test('moves fixed line to the end', async t => {
     error: t.end,
     next: output => {
       t.equal(output, `${WARN} foo` + EOL +
-        `Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('1')}, done`)
+        `Progress: resolved ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('1')}, added ${hlValue('0')}, done`)
     },
   })
 
@@ -278,33 +324,33 @@ test('prints progress of big files download', async t => {
     map((output, index) => {
       switch (index) {
       case 0:
-        t.equal(output, `Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}`)
+        t.equal(output, `Progress: resolved ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}, added ${hlValue('0')}`)
         return
       case 1:
         t.equal(output, `\
-Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}
+Progress: resolved ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}, added ${hlValue('0')}
 Downloading ${hlPkgId(pkgId1)}: ${hlValue('0 B')}/${hlValue('10.5 MB')}`)
         return
       case 2:
         t.equal(output, `\
-Resolving: total ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}
+Progress: resolved ${hlValue('1')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}, added ${hlValue('0')}
 Downloading ${hlPkgId(pkgId1)}: ${hlValue('5.77 MB')}/${hlValue('10.5 MB')}`)
         return
       case 4:
         t.equal(output, `\
-Resolving: total ${hlValue('2')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}
+Progress: resolved ${hlValue('2')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}, added ${hlValue('0')}
 Downloading ${hlPkgId(pkgId1)}: ${hlValue('7.34 MB')}/${hlValue('10.5 MB')}`, 'downloading of small package not reported')
         return
       case 7:
         t.equal(output, `\
-Resolving: total ${hlValue('3')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}
+Progress: resolved ${hlValue('3')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}, added ${hlValue('0')}
 Downloading ${hlPkgId(pkgId1)}: ${hlValue('7.34 MB')}/${hlValue('10.5 MB')}
 Downloading ${hlPkgId(pkgId3)}: ${hlValue('19.9 MB')}/${hlValue('21 MB')}`)
         return
       case 8:
         t.equal(output, `\
 Downloading ${hlPkgId(pkgId1)}: ${hlValue('10.5 MB')}/${hlValue('10.5 MB')}, done
-Resolving: total ${hlValue('3')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}
+Progress: resolved ${hlValue('3')}, reused ${hlValue('0')}, downloaded ${hlValue('0')}, added ${hlValue('0')}
 Downloading ${hlPkgId(pkgId3)}: ${hlValue('19.9 MB')}/${hlValue('21 MB')}`)
         return // eslint-disable-line
       }

packages/headless/src/index.ts

@@ -224,6 +224,7 @@ export default async (opts: HeadlessOptions) => {
     }),
     linkAllPkgs(opts.storeController, depNodes, {
       force: opts.force,
+      lockfileDir: opts.lockfileDir,
       targetEngine: opts.sideEffectsCacheRead && ENGINE_NAME || undefined,
     }),
   ])
@@ -646,6 +647,7 @@ function linkAllPkgs (
   depNodes: DependenciesGraphNode[],
   opts: {
     force: boolean
+    lockfileDir: string
     targetEngine?: string
   }
 ) {
@@ -653,11 +655,19 @@ function linkAllPkgs (
     depNodes.map(async (depNode) => {
       const filesResponse = await depNode.fetchingFiles()
 
-      const { isBuilt } = await storeController.importPackage(depNode.dir, {
+      const { importMethod, isBuilt } = await storeController.importPackage(depNode.dir, {
         filesResponse,
         force: opts.force,
         targetEngine: opts.targetEngine,
       })
+      if (importMethod) {
+        progressLogger.debug({
+          method: importMethod,
+          requester: opts.lockfileDir,
+          status: 'imported',
+          to: depNode.dir,
+        })
+      }
       depNode.isBuilt = isBuilt
     })
   )

packages/package-store/src/storeController/createImportPackage.ts

@@ -1,4 +1,4 @@
-import { importingLogger, packageImportMethodLogger } from '@pnpm/core-loggers'
+import { packageImportMethodLogger } from '@pnpm/core-loggers'
 import { globalInfo, globalWarn } from '@pnpm/logger'
 import importIndexedDir, { ImportFile } from '../fs/importIndexedDir'
 import path = require('path')
@@ -14,15 +14,13 @@ interface ImportOptions {
   fromStore: boolean
 }
 
-type ImportFunction = (to: string, opts: ImportOptions) => Promise<void>
+type ImportFunction = (to: string, opts: ImportOptions) => Promise<string | undefined>
 
 export default (
   packageImportMethod?: 'auto' | 'hardlink' | 'copy' | 'clone'
 ): ImportFunction => {
   const importPackage = createImportPackage(packageImportMethod)
-  return (to, opts) => limitLinking(async () => {
-    await importPackage(to, opts)
-  })
+  return (to, opts) => limitLinking(() => importPackage(to, opts))
 }
 
 function createImportPackage (packageImportMethod?: 'auto' | 'hardlink' | 'copy' | 'clone') {
@@ -52,34 +50,32 @@ function createImportPackage (packageImportMethod?: 'auto' | 'hardlink' | 'copy'
 function createAutoImporter (): ImportFunction {
   let auto = initialAuto
 
-  return async (to, opts) => {
-    await auto(to, opts)
-  }
+  return (to, opts) => auto(to, opts)
 
   async function initialAuto (
     to: string,
     opts: ImportOptions
-  ): Promise<boolean> {
+  ): Promise<string | undefined> {
     try {
-      if (!await clonePkg(to, opts)) return false
+      if (!await clonePkg(to, opts)) return undefined
       packageImportMethodLogger.debug({ method: 'clone' })
       auto = clonePkg
-      return true
+      return 'clone'
     } catch (err) {
       // ignore
     }
     try {
-      if (!await hardlinkPkg(fs.link, to, opts)) return false
+      if (!await hardlinkPkg(fs.link, to, opts)) return undefined
       packageImportMethodLogger.debug({ method: 'hardlink' })
       auto = hardlinkPkg.bind(null, linkOrCopy)
-      return true
+      return 'hardlink'
     } catch (err) {
       if (err.code === 'EINVAL') {
         // This error sometimes happens on Windows.
         // We still choose hard linking that will fall back to copying in edge cases.
         packageImportMethodLogger.debug({ method: 'hardlink' })
         auto = hardlinkPkg.bind(null, linkOrCopy)
-        return true
+        return 'hardlink'
       }
       if (!err.message.startsWith('EXDEV: cross-device link not permitted')) throw err
       globalWarn(err.message)
@@ -99,10 +95,9 @@ async function clonePkg (
 
   if (!opts.fromStore || opts.force || !await exists(pkgJsonPath)) {
     await importIndexedDir(cloneFile, to, opts.filesMap)
-    importingLogger.debug({ to, method: 'clone' })
-    return true
+    return 'clone'
   }
-  return false
+  return undefined
 }
 
 async function cloneFile (from: string, to: string) {
@@ -118,10 +113,9 @@ async function hardlinkPkg (
 
   if (!opts.fromStore || opts.force || !await exists(pkgJsonPath) || !await pkgLinkedToStore(pkgJsonPath, opts.filesMap['package.json'], to)) {
     await importIndexedDir(importFile, to, opts.filesMap)
-    importingLogger.debug({ to, method: 'hardlink' })
-    return true
+    return 'hardlink'
   }
-  return false
+  return undefined
 }
 
 async function linkOrCopy (existingPath: string, newPath: string) {
@@ -158,8 +152,7 @@ export async function copyPkg (
 
   if (!opts.fromStore || opts.force || !await exists(pkgJsonPath)) {
     await importIndexedDir(fs.copyFile, to, opts.filesMap)
-    importingLogger.debug({ to, method: 'copy' })
-    return true
+    return 'copy'
   }
-  return false
+  return undefined
 }

packages/package-store/src/storeController/index.ts

@@ -52,8 +52,8 @@ export default async function (
     for (const [fileName, fileMeta] of Object.entries(filesIndex)) {
       filesMap[fileName] = getFilePathByModeInCafs(fileMeta.integrity, fileMeta.mode)
     }
-    await impPkg(to, { filesMap, fromStore: opts.filesResponse.fromStore, force: opts.force })
-    return { isBuilt }
+    const importMethod = await impPkg(to, { filesMap, fromStore: opts.filesResponse.fromStore, force: opts.force })
+    return { importMethod, isBuilt }
   }
 
   return {

packages/server/src/connectStoreController.ts

@@ -37,7 +37,7 @@ export default function (
         return limitedFetch(`${remotePrefix}/importPackage`, {
           opts,
           to,
-        }) as Promise<{ isBuilt: boolean }>
+        }) as Promise<{ importMethod: string | undefined, isBuilt: boolean }>
       },
       prune: async () => {
         await limitedFetch(`${remotePrefix}/prune`, {})

packages/store-controller-types/src/index.ts

@@ -61,7 +61,7 @@ export type ImportPackageFunction = (
     filesResponse: PackageFilesResponse
     force: boolean
   }
-) => Promise<{ isBuilt: boolean }>
+) => Promise<{ isBuilt: boolean, importMethod: undefined | string }>
 
 export interface PackageFileInfo {
   integrity: string

packages/supi/src/install/link.ts

@@ -1,5 +1,6 @@
 import { ENGINE_NAME } from '@pnpm/constants'
 import {
+  progressLogger,
   rootLogger,
   stageLogger,
   statsLogger,
@@ -317,6 +318,7 @@ async function linkNewPackages (
     }),
     linkAllPkgs(opts.storeController, newPkgs, {
       force: opts.force,
+      lockfileDir: opts.lockfileDir,
       targetEngine: opts.sideEffectsCacheRead && ENGINE_NAME || undefined,
     }),
   ])
@@ -362,6 +364,7 @@ function linkAllPkgs (
   depNodes: DependenciesGraphNode[],
   opts: {
     force: boolean
+    lockfileDir: string
     targetEngine?: string
   }
 ) {
@@ -369,11 +372,19 @@ function linkAllPkgs (
     depNodes.map(async (depNode) => {
       const filesResponse = await depNode.fetchingFiles()
 
-      const { isBuilt } = await storeController.importPackage(depNode.dir, {
+      const { importMethod, isBuilt } = await storeController.importPackage(depNode.dir, {
         filesResponse,
         force: opts.force,
         targetEngine: opts.targetEngine,
       })
+      if (importMethod) {
+        progressLogger.debug({
+          method: importMethod,
+          requester: opts.lockfileDir,
+          status: 'imported',
+          to: depNode.dir,
+        })
+      }
       depNode.isBuilt = isBuilt
     })
   )